5043: Use Go's log package to serialize writes. Lose logChan.
[arvados.git] / services / crunchstat / crunchstat.go
1 package main
2
3 import (
4         "bufio"
5         "bytes"
6         "errors"
7         "flag"
8         "fmt"
9         "io"
10         "io/ioutil"
11         "log"
12         "os"
13         "os/exec"
14         "os/signal"
15         "strconv"
16         "strings"
17         "syscall"
18         "time"
19 )
20
21 /*
22 #include <unistd.h>
23 #include <sys/types.h>
24 #include <pwd.h>
25 #include <stdlib.h>
26 */
27 import "C"
28
29 // The above block of magic allows us to look up user_hz via _SC_CLK_TCK.
30
31 type Cgroup struct {
32         root   string
33         parent string
34         cid    string
35 }
36
37 var childLog = log.New(os.Stderr, "", 0)
38 var statLog = log.New(os.Stderr, "crunchstat: ", 0)
39
40 func CopyPipeToChildLog(in io.ReadCloser, done chan<- bool) {
41         reader := bufio.NewReader(in)
42         for {
43                 line, err := reader.ReadBytes('\n')
44                 if len(line) > 0 {
45                         if err == nil {
46                                 // err == nil IFF line ends in \n
47                                 line = line[:len(line)-1]
48                         }
49                         childLog.Println(string(line))
50                 }
51                 if err == io.EOF {
52                         break
53                 } else if err != nil {
54                         statLog.Fatalln("line buffering error:", err)
55                 }
56         }
57         done <- true
58         in.Close()
59 }
60
61 func ReadAllOrWarn(in *os.File) ([]byte, error) {
62         content, err := ioutil.ReadAll(in)
63         if err != nil {
64                 statLog.Printf("read %s: %s\n", in.Name(), err)
65         }
66         return content, err
67 }
68
69 var reportedStatFile = map[string]string{}
70
71 // Open the cgroup stats file in /sys/fs corresponding to the target
72 // cgroup, and return an *os.File. If no stats file is available,
73 // return nil.
74 //
75 // TODO: Instead of trying all options, choose a process in the
76 // container, and read /proc/PID/cgroup to determine the appropriate
77 // cgroup root for the given statgroup. (This will avoid falling back
78 // to host-level stats during container setup and teardown.)
79 func OpenStatFile(cgroup Cgroup, statgroup string, stat string) (*os.File, error) {
80         var paths = []string{
81                 fmt.Sprintf("%s/%s/%s/%s/%s", cgroup.root, statgroup, cgroup.parent, cgroup.cid, stat),
82                 fmt.Sprintf("%s/%s/%s/%s", cgroup.root, cgroup.parent, cgroup.cid, stat),
83                 fmt.Sprintf("%s/%s/%s", cgroup.root, statgroup, stat),
84                 fmt.Sprintf("%s/%s", cgroup.root, stat),
85         }
86         var path string
87         var file *os.File
88         var err error
89         for _, path = range paths {
90                 file, err = os.Open(path)
91                 if err == nil {
92                         break
93                 } else {
94                         path = ""
95                 }
96         }
97         if pathWas, ok := reportedStatFile[stat]; !ok || pathWas != path {
98                 // Log whenever we start using a new/different cgroup
99                 // stat file for a given statistic. This typically
100                 // happens 1 to 3 times per statistic, depending on
101                 // whether we happen to collect stats [a] before any
102                 // processes have been created in the container and
103                 // [b] after all contained processes have exited.
104                 reportedStatFile[stat] = path
105                 if path == "" {
106                         statLog.Printf("did not find stats file: stat %s, statgroup %s, cid %s, parent %s, root %s\n", stat, statgroup, cgroup.cid, cgroup.parent, cgroup.root)
107                 } else {
108                         statLog.Printf("reading stats from %s\n", path)
109                 }
110         }
111         return file, err
112 }
113
114 func GetContainerNetStats(cgroup Cgroup) (io.Reader, error) {
115         procsFile, err := OpenStatFile(cgroup, "cpuacct", "cgroup.procs")
116         if err != nil {
117                 return nil, err
118         }
119         defer procsFile.Close()
120         reader := bufio.NewScanner(procsFile)
121         for reader.Scan() {
122                 taskPid := reader.Text()
123                 statsFilename := fmt.Sprintf("/proc/%s/net/dev", taskPid)
124                 stats, err := ioutil.ReadFile(statsFilename)
125                 if err != nil {
126                         statLog.Printf("read %s: %s\n", statsFilename, err)
127                         continue
128                 }
129                 return strings.NewReader(string(stats)), nil
130         }
131         return nil, errors.New("Could not read stats for any proc in container")
132 }
133
134 type IoSample struct {
135         sampleTime time.Time
136         txBytes    int64
137         rxBytes    int64
138 }
139
140 func DoBlkIoStats(cgroup Cgroup, lastSample map[string]IoSample) {
141         c, err := OpenStatFile(cgroup, "blkio", "blkio.io_service_bytes")
142         if err != nil {
143                 return
144         }
145         defer c.Close()
146         b := bufio.NewScanner(c)
147         var sampleTime = time.Now()
148         newSamples := make(map[string]IoSample)
149         for b.Scan() {
150                 var device, op string
151                 var val int64
152                 if _, err := fmt.Sscanf(string(b.Text()), "%s %s %d", &device, &op, &val); err != nil {
153                         continue
154                 }
155                 var thisSample IoSample
156                 var ok bool
157                 if thisSample, ok = newSamples[device]; !ok {
158                         thisSample = IoSample{sampleTime, -1, -1}
159                 }
160                 switch op {
161                 case "Read":
162                         thisSample.rxBytes = val
163                 case "Write":
164                         thisSample.txBytes = val
165                 }
166                 newSamples[device] = thisSample
167         }
168         for dev, sample := range newSamples {
169                 if sample.txBytes < 0 || sample.rxBytes < 0 {
170                         continue
171                 }
172                 delta := ""
173                 if prev, ok := lastSample[dev]; ok {
174                         delta = fmt.Sprintf(" -- interval %.4f seconds %d write %d read",
175                                 sample.sampleTime.Sub(prev.sampleTime).Seconds(),
176                                 sample.txBytes-prev.txBytes,
177                                 sample.rxBytes-prev.rxBytes)
178                 }
179                 statLog.Printf("blkio:%s %d write %d read%s\n", dev, sample.txBytes, sample.rxBytes, delta)
180                 lastSample[dev] = sample
181         }
182 }
183
184 type MemSample struct {
185         sampleTime time.Time
186         memStat    map[string]int64
187 }
188
189 func DoMemoryStats(cgroup Cgroup) {
190         c, err := OpenStatFile(cgroup, "memory", "memory.stat")
191         if err != nil {
192                 return
193         }
194         defer c.Close()
195         b := bufio.NewScanner(c)
196         thisSample := MemSample{time.Now(), make(map[string]int64)}
197         wantStats := [...]string{"cache", "swap", "pgmajfault", "rss"}
198         for b.Scan() {
199                 var stat string
200                 var val int64
201                 if _, err := fmt.Sscanf(string(b.Text()), "%s %d", &stat, &val); err != nil {
202                         continue
203                 }
204                 thisSample.memStat[stat] = val
205         }
206         var outstat bytes.Buffer
207         for _, key := range wantStats {
208                 if val, ok := thisSample.memStat[key]; ok {
209                         outstat.WriteString(fmt.Sprintf(" %d %s", val, key))
210                 }
211         }
212         statLog.Printf("mem%s\n", outstat.String())
213 }
214
215 func DoNetworkStats(cgroup Cgroup, lastSample map[string]IoSample) {
216         sampleTime := time.Now()
217         stats, err := GetContainerNetStats(cgroup)
218         if err != nil {
219                 return
220         }
221
222         scanner := bufio.NewScanner(stats)
223         for scanner.Scan() {
224                 var ifName string
225                 var rx, tx int64
226                 words := strings.Fields(scanner.Text())
227                 if len(words) != 17 {
228                         // Skip lines with wrong format
229                         continue
230                 }
231                 ifName = strings.TrimRight(words[0], ":")
232                 if ifName == "lo" || ifName == "" {
233                         // Skip loopback interface and lines with wrong format
234                         continue
235                 }
236                 if tx, err = strconv.ParseInt(words[9], 10, 64); err != nil {
237                         continue
238                 }
239                 if rx, err = strconv.ParseInt(words[1], 10, 64); err != nil {
240                         continue
241                 }
242                 nextSample := IoSample{}
243                 nextSample.sampleTime = sampleTime
244                 nextSample.txBytes = tx
245                 nextSample.rxBytes = rx
246                 var delta string
247                 if prev, ok := lastSample[ifName]; ok {
248                         interval := nextSample.sampleTime.Sub(prev.sampleTime).Seconds()
249                         delta = fmt.Sprintf(" -- interval %.4f seconds %d tx %d rx",
250                                 interval,
251                                 tx-prev.txBytes,
252                                 rx-prev.rxBytes)
253                 }
254                 statLog.Printf("net:%s %d tx %d rx%s\n", ifName, tx, rx, delta)
255                 lastSample[ifName] = nextSample
256         }
257 }
258
259 type CpuSample struct {
260         hasData    bool // to distinguish the zero value from real data
261         sampleTime time.Time
262         user       float64
263         sys        float64
264         cpus       int64
265 }
266
267 // Return the number of CPUs available in the container. Return 0 if
268 // we can't figure out the real number of CPUs.
269 func GetCpuCount(cgroup Cgroup) int64 {
270         cpusetFile, err := OpenStatFile(cgroup, "cpuset", "cpuset.cpus")
271         if err != nil {
272                 return 0
273         }
274         defer cpusetFile.Close()
275         b, err := ReadAllOrWarn(cpusetFile)
276         sp := strings.Split(string(b), ",")
277         cpus := int64(0)
278         for _, v := range sp {
279                 var min, max int64
280                 n, _ := fmt.Sscanf(v, "%d-%d", &min, &max)
281                 if n == 2 {
282                         cpus += (max - min) + 1
283                 } else {
284                         cpus += 1
285                 }
286         }
287         return cpus
288 }
289
290 func DoCpuStats(cgroup Cgroup, lastSample *CpuSample) {
291         statFile, err := OpenStatFile(cgroup, "cpuacct", "cpuacct.stat")
292         if err != nil {
293                 return
294         }
295         defer statFile.Close()
296         b, err := ReadAllOrWarn(statFile)
297         if err != nil {
298                 return
299         }
300
301         nextSample := CpuSample{true, time.Now(), 0, 0, GetCpuCount(cgroup)}
302         var userTicks, sysTicks int64
303         fmt.Sscanf(string(b), "user %d\nsystem %d", &userTicks, &sysTicks)
304         user_hz := float64(C.sysconf(C._SC_CLK_TCK))
305         nextSample.user = float64(userTicks) / user_hz
306         nextSample.sys = float64(sysTicks) / user_hz
307
308         delta := ""
309         if lastSample.hasData {
310                 delta = fmt.Sprintf(" -- interval %.4f seconds %.4f user %.4f sys",
311                         nextSample.sampleTime.Sub(lastSample.sampleTime).Seconds(),
312                         nextSample.user-lastSample.user,
313                         nextSample.sys-lastSample.sys)
314         }
315         statLog.Printf("cpu %.4f user %.4f sys %d cpus%s\n",
316                 nextSample.user, nextSample.sys, nextSample.cpus, delta)
317         *lastSample = nextSample
318 }
319
320 func PollCgroupStats(cgroup Cgroup, poll int64, stop_poll_chan <-chan bool) {
321         var lastNetSample = map[string]IoSample{}
322         var lastDiskSample = map[string]IoSample{}
323         var lastCpuSample = CpuSample{}
324
325         poll_chan := make(chan bool, 1)
326         go func() {
327                 // Send periodic poll events.
328                 poll_chan <- true
329                 for {
330                         time.Sleep(time.Duration(poll) * time.Millisecond)
331                         poll_chan <- true
332                 }
333         }()
334         for {
335                 select {
336                 case <-stop_poll_chan:
337                         return
338                 case <-poll_chan:
339                         // Emit stats, then select again.
340                 }
341                 DoMemoryStats(cgroup)
342                 DoCpuStats(cgroup, &lastCpuSample)
343                 DoBlkIoStats(cgroup, lastDiskSample)
344                 DoNetworkStats(cgroup, lastNetSample)
345         }
346 }
347
348 func run(logger *log.Logger) error {
349
350         var (
351                 cgroup_root    string
352                 cgroup_parent  string
353                 cgroup_cidfile string
354                 wait           int64
355                 poll           int64
356         )
357
358         flag.StringVar(&cgroup_root, "cgroup-root", "", "Root of cgroup tree")
359         flag.StringVar(&cgroup_parent, "cgroup-parent", "", "Name of container parent under cgroup")
360         flag.StringVar(&cgroup_cidfile, "cgroup-cid", "", "Path to container id file")
361         flag.Int64Var(&wait, "wait", 5, "Maximum time (in seconds) to wait for cid file to show up")
362         flag.Int64Var(&poll, "poll", 1000, "Polling frequency, in milliseconds")
363
364         flag.Parse()
365
366         if cgroup_root == "" {
367                 statLog.Fatalln("Must provide -cgroup-root")
368         }
369
370         finish_chan := make(chan bool)
371         defer close(finish_chan)
372
373         var cmd *exec.Cmd
374
375         if len(flag.Args()) > 0 {
376                 // Set up subprocess
377                 cmd = exec.Command(flag.Args()[0], flag.Args()[1:]...)
378
379                 statLog.Println("Running ", flag.Args())
380
381                 // Child process will use our stdin and stdout pipes
382                 // (we close our copies below)
383                 cmd.Stdin = os.Stdin
384                 cmd.Stdout = os.Stdout
385
386                 // Forward SIGINT and SIGTERM to inner process
387                 sigChan := make(chan os.Signal, 1)
388                 go func(sig <-chan os.Signal) {
389                         catch := <-sig
390                         if cmd.Process != nil {
391                                 cmd.Process.Signal(catch)
392                         }
393                         statLog.Println("caught signal:", catch)
394                 }(sigChan)
395                 signal.Notify(sigChan, syscall.SIGTERM)
396                 signal.Notify(sigChan, syscall.SIGINT)
397
398                 // Funnel stderr through our channel
399                 stderr_pipe, err := cmd.StderrPipe()
400                 if err != nil {
401                         statLog.Fatalln("stderr:", err)
402                 }
403                 go CopyPipeToChildLog(stderr_pipe, finish_chan)
404
405                 // Run subprocess
406                 if err := cmd.Start(); err != nil {
407                         statLog.Fatalln("cmd.Start:", err)
408                 }
409
410                 // Close stdin/stdout in this (parent) process
411                 os.Stdin.Close()
412                 os.Stdout.Close()
413         }
414
415         // Read the cid file
416         var container_id string
417         if cgroup_cidfile != "" {
418                 // wait up to 'wait' seconds for the cid file to appear
419                 ok := false
420                 var i time.Duration
421                 for i = 0; i < time.Duration(wait)*time.Second; i += (100 * time.Millisecond) {
422                         cid, err := ioutil.ReadFile(cgroup_cidfile)
423                         if err == nil && len(cid) > 0 {
424                                 ok = true
425                                 container_id = string(cid)
426                                 break
427                         }
428                         time.Sleep(100 * time.Millisecond)
429                 }
430                 if !ok {
431                         statLog.Println("Could not read cid file:", cgroup_cidfile)
432                 }
433         }
434
435         stop_poll_chan := make(chan bool, 1)
436         cgroup := Cgroup{cgroup_root, cgroup_parent, container_id}
437         go PollCgroupStats(cgroup, poll, stop_poll_chan)
438
439         // When the child exits, tell the polling goroutine to stop.
440         defer func() { stop_poll_chan <- true }()
441
442         // Wait for CopyPipeToChan to consume child's stderr pipe
443         <-finish_chan
444
445         return cmd.Wait()
446 }
447
448 func main() {
449         logger := log.New(os.Stderr, "crunchstat: ", 0)
450         if err := run(logger); err != nil {
451                 if exiterr, ok := err.(*exec.ExitError); ok {
452                         // The program has exited with an exit code != 0
453
454                         // This works on both Unix and
455                         // Windows. Although package syscall is
456                         // generally platform dependent, WaitStatus is
457                         // defined for both Unix and Windows and in
458                         // both cases has an ExitStatus() method with
459                         // the same signature.
460                         if status, ok := exiterr.Sys().(syscall.WaitStatus); ok {
461                                 os.Exit(status.ExitStatus())
462                         }
463                 } else {
464                         statLog.Fatalln("cmd.Wait:", err)
465                 }
466         }
467 }