lib/crunchstat/crunchstat.go

   1 // Copyright (C) The Arvados Authors. All rights reserved.
   2 //
   3 // SPDX-License-Identifier: AGPL-3.0
   4
   5 // Package crunchstat reports resource usage (CPU, memory, disk,
   6 // network) for a cgroup.
   7 package crunchstat
   8
   9 import (
  10         "bufio"
  11         "bytes"
  12         "errors"
  13         "fmt"
  14         "io"
  15         "io/ioutil"
  16         "log"
  17         "os"
  18         "strconv"
  19         "strings"
  20         "syscall"
  21         "time"
  22 )
  23
  24 // This magically allows us to look up userHz via _SC_CLK_TCK:
  25
  26 /*
  27 #include <unistd.h>
  28 #include <sys/types.h>
  29 #include <pwd.h>
  30 #include <stdlib.h>
  31 */
  32 import "C"
  33
  34 // A Reporter gathers statistics for a cgroup and writes them to a
  35 // log.Logger.
  36 type Reporter struct {
  37         // CID of the container to monitor. If empty, read the CID
  38         // from CIDFile (first waiting until a non-empty file appears
  39         // at CIDFile). If CIDFile is also empty, report host
  40         // statistics.
  41         CID string
  42
  43         // Path to a file we can read CID from.
  44         CIDFile string
  45
  46         // Where cgroup accounting files live on this system, e.g.,
  47         // "/sys/fs/cgroup".
  48         CgroupRoot string
  49
  50         // Parent cgroup, e.g., "docker".
  51         CgroupParent string
  52
  53         // Interval between samples. Must be positive.
  54         PollPeriod time.Duration
  55
  56         // Temporary directory, will be monitored for available, used & total space.
  57         TempDir string
  58
  59         // Where to write statistics. Must not be nil.
  60         Logger *log.Logger
  61
  62         reportedStatFile    map[string]string
  63         lastNetSample       map[string]ioSample
  64         lastDiskIOSample    map[string]ioSample
  65         lastCPUSample       cpuSample
  66         lastDiskSpaceSample diskSpaceSample
  67
  68         done    chan struct{} // closed when we should stop reporting
  69         flushed chan struct{} // closed when we have made our last report
  70 }
  71
  72 // Start starts monitoring in a new goroutine, and returns
  73 // immediately.
  74 //
  75 // The monitoring goroutine waits for a non-empty CIDFile to appear
  76 // (unless CID is non-empty). Then it waits for the accounting files
  77 // to appear for the monitored container. Then it collects and reports
  78 // statistics until Stop is called.
  79 //
  80 // Callers should not call Start more than once.
  81 //
  82 // Callers should not modify public data fields after calling Start.
  83 func (r *Reporter) Start() {
  84         r.done = make(chan struct{})
  85         r.flushed = make(chan struct{})
  86         go r.run()
  87 }
  88
  89 // Stop reporting. Do not call more than once, or before calling
  90 // Start.
  91 //
  92 // Nothing will be logged after Stop returns.
  93 func (r *Reporter) Stop() {
  94         close(r.done)
  95         <-r.flushed
  96 }
  97
  98 func (r *Reporter) readAllOrWarn(in io.Reader) ([]byte, error) {
  99         content, err := ioutil.ReadAll(in)
 100         if err != nil {
 101                 r.Logger.Printf("warning: %v", err)
 102         }
 103         return content, err
 104 }
 105
 106 // Open the cgroup stats file in /sys/fs corresponding to the target
 107 // cgroup, and return an io.ReadCloser. If no stats file is available,
 108 // return nil.
 109 //
 110 // Log the file that was opened, if it isn't the same file opened on
 111 // the last openStatFile for this stat.
 112 //
 113 // Log "not available" if no file is found and either this stat has
 114 // been available in the past, or verbose==true.
 115 //
 116 // TODO: Instead of trying all options, choose a process in the
 117 // container, and read /proc/PID/cgroup to determine the appropriate
 118 // cgroup root for the given statgroup. (This will avoid falling back
 119 // to host-level stats during container setup and teardown.)
 120 func (r *Reporter) openStatFile(statgroup, stat string, verbose bool) (io.ReadCloser, error) {
 121         var paths []string
 122         if r.CID != "" {
 123                 // Collect container's stats
 124                 paths = []string{
 125                         fmt.Sprintf("%s/%s/%s/%s/%s", r.CgroupRoot, statgroup, r.CgroupParent, r.CID, stat),
 126                         fmt.Sprintf("%s/%s/%s/%s", r.CgroupRoot, r.CgroupParent, r.CID, stat),
 127                 }
 128         } else {
 129                 // Collect this host's stats
 130                 paths = []string{
 131                         fmt.Sprintf("%s/%s/%s", r.CgroupRoot, statgroup, stat),
 132                         fmt.Sprintf("%s/%s", r.CgroupRoot, stat),
 133                 }
 134         }
 135         var path string
 136         var file *os.File
 137         var err error
 138         for _, path = range paths {
 139                 file, err = os.Open(path)
 140                 if err == nil {
 141                         break
 142                 } else {
 143                         path = ""
 144                 }
 145         }
 146         if pathWas := r.reportedStatFile[stat]; pathWas != path {
 147                 // Log whenever we start using a new/different cgroup
 148                 // stat file for a given statistic. This typically
 149                 // happens 1 to 3 times per statistic, depending on
 150                 // whether we happen to collect stats [a] before any
 151                 // processes have been created in the container and
 152                 // [b] after all contained processes have exited.
 153                 if path == "" && verbose {
 154                         r.Logger.Printf("notice: stats not available: stat %s, statgroup %s, cid %s, parent %s, root %s\n", stat, statgroup, r.CID, r.CgroupParent, r.CgroupRoot)
 155                 } else if pathWas != "" {
 156                         r.Logger.Printf("notice: stats moved from %s to %s\n", r.reportedStatFile[stat], path)
 157                 } else {
 158                         r.Logger.Printf("notice: reading stats from %s\n", path)
 159                 }
 160                 r.reportedStatFile[stat] = path
 161         }
 162         return file, err
 163 }
 164
 165 func (r *Reporter) getContainerNetStats() (io.Reader, error) {
 166         procsFile, err := r.openStatFile("cpuacct", "cgroup.procs", true)
 167         if err != nil {
 168                 return nil, err
 169         }
 170         defer procsFile.Close()
 171         reader := bufio.NewScanner(procsFile)
 172         for reader.Scan() {
 173                 taskPid := reader.Text()
 174                 statsFilename := fmt.Sprintf("/proc/%s/net/dev", taskPid)
 175                 stats, err := ioutil.ReadFile(statsFilename)
 176                 if err != nil {
 177                         r.Logger.Printf("notice: %v", err)
 178                         continue
 179                 }
 180                 return strings.NewReader(string(stats)), nil
 181         }
 182         return nil, errors.New("Could not read stats for any proc in container")
 183 }
 184
 185 type ioSample struct {
 186         sampleTime time.Time
 187         txBytes    int64
 188         rxBytes    int64
 189 }
 190
 191 func (r *Reporter) doBlkIOStats() {
 192         c, err := r.openStatFile("blkio", "blkio.io_service_bytes", true)
 193         if err != nil {
 194                 return
 195         }
 196         defer c.Close()
 197         b := bufio.NewScanner(c)
 198         var sampleTime = time.Now()
 199         newSamples := make(map[string]ioSample)
 200         for b.Scan() {
 201                 var device, op string
 202                 var val int64
 203                 if _, err := fmt.Sscanf(string(b.Text()), "%s %s %d", &device, &op, &val); err != nil {
 204                         continue
 205                 }
 206                 var thisSample ioSample
 207                 var ok bool
 208                 if thisSample, ok = newSamples[device]; !ok {
 209                         thisSample = ioSample{sampleTime, -1, -1}
 210                 }
 211                 switch op {
 212                 case "Read":
 213                         thisSample.rxBytes = val
 214                 case "Write":
 215                         thisSample.txBytes = val
 216                 }
 217                 newSamples[device] = thisSample
 218         }
 219         for dev, sample := range newSamples {
 220                 if sample.txBytes < 0 || sample.rxBytes < 0 {
 221                         continue
 222                 }
 223                 delta := ""
 224                 if prev, ok := r.lastDiskIOSample[dev]; ok {
 225                         delta = fmt.Sprintf(" -- interval %.4f seconds %d write %d read",
 226                                 sample.sampleTime.Sub(prev.sampleTime).Seconds(),
 227                                 sample.txBytes-prev.txBytes,
 228                                 sample.rxBytes-prev.rxBytes)
 229                 }
 230                 r.Logger.Printf("blkio:%s %d write %d read%s\n", dev, sample.txBytes, sample.rxBytes, delta)
 231                 r.lastDiskIOSample[dev] = sample
 232         }
 233 }
 234
 235 type memSample struct {
 236         sampleTime time.Time
 237         memStat    map[string]int64
 238 }
 239
 240 func (r *Reporter) doMemoryStats() {
 241         c, err := r.openStatFile("memory", "memory.stat", true)
 242         if err != nil {
 243                 return
 244         }
 245         defer c.Close()
 246         b := bufio.NewScanner(c)
 247         thisSample := memSample{time.Now(), make(map[string]int64)}
 248         wantStats := [...]string{"cache", "swap", "pgmajfault", "rss"}
 249         for b.Scan() {
 250                 var stat string
 251                 var val int64
 252                 if _, err := fmt.Sscanf(string(b.Text()), "%s %d", &stat, &val); err != nil {
 253                         continue
 254                 }
 255                 thisSample.memStat[stat] = val
 256         }
 257         var outstat bytes.Buffer
 258         for _, key := range wantStats {
 259                 // Use "total_X" stats (entire hierarchy) if enabled,
 260                 // otherwise just the single cgroup -- see
 261                 // https://www.kernel.org/doc/Documentation/cgroup-v1/memory.txt
 262                 if val, ok := thisSample.memStat["total_"+key]; ok {
 263                         fmt.Fprintf(&outstat, " %d %s", val, key)
 264                 } else if val, ok := thisSample.memStat[key]; ok {
 265                         fmt.Fprintf(&outstat, " %d %s", val, key)
 266                 }
 267         }
 268         r.Logger.Printf("mem%s\n", outstat.String())
 269 }
 270
 271 func (r *Reporter) doNetworkStats() {
 272         sampleTime := time.Now()
 273         stats, err := r.getContainerNetStats()
 274         if err != nil {
 275                 return
 276         }
 277
 278         scanner := bufio.NewScanner(stats)
 279         for scanner.Scan() {
 280                 var ifName string
 281                 var rx, tx int64
 282                 words := strings.Fields(scanner.Text())
 283                 if len(words) != 17 {
 284                         // Skip lines with wrong format
 285                         continue
 286                 }
 287                 ifName = strings.TrimRight(words[0], ":")
 288                 if ifName == "lo" || ifName == "" {
 289                         // Skip loopback interface and lines with wrong format
 290                         continue
 291                 }
 292                 if tx, err = strconv.ParseInt(words[9], 10, 64); err != nil {
 293                         continue
 294                 }
 295                 if rx, err = strconv.ParseInt(words[1], 10, 64); err != nil {
 296                         continue
 297                 }
 298                 nextSample := ioSample{}
 299                 nextSample.sampleTime = sampleTime
 300                 nextSample.txBytes = tx
 301                 nextSample.rxBytes = rx
 302                 var delta string
 303                 if prev, ok := r.lastNetSample[ifName]; ok {
 304                         interval := nextSample.sampleTime.Sub(prev.sampleTime).Seconds()
 305                         delta = fmt.Sprintf(" -- interval %.4f seconds %d tx %d rx",
 306                                 interval,
 307                                 tx-prev.txBytes,
 308                                 rx-prev.rxBytes)
 309                 }
 310                 r.Logger.Printf("net:%s %d tx %d rx%s\n", ifName, tx, rx, delta)
 311                 r.lastNetSample[ifName] = nextSample
 312         }
 313 }
 314
 315 type diskSpaceSample struct {
 316         hasData    bool
 317         sampleTime time.Time
 318         total      uint64
 319         used       uint64
 320         available  uint64
 321 }
 322
 323 func (r *Reporter) doDiskSpaceStats() {
 324         s := syscall.Statfs_t{}
 325         err := syscall.Statfs(r.TempDir, &s)
 326         if err != nil {
 327                 return
 328         }
 329         bs := uint64(s.Bsize)
 330         nextSample := diskSpaceSample{
 331                 hasData:    true,
 332                 sampleTime: time.Now(),
 333                 total:      s.Blocks * bs,
 334                 used:       (s.Blocks - s.Bfree) * bs,
 335                 available:  s.Bavail * bs,
 336         }
 337
 338         var delta string
 339         if r.lastDiskSpaceSample.hasData {
 340                 prev := r.lastDiskSpaceSample
 341                 interval := nextSample.sampleTime.Sub(prev.sampleTime).Seconds()
 342                 delta = fmt.Sprintf(" -- interval %.4f seconds %d used",
 343                         interval,
 344                         int64(nextSample.used-prev.used))
 345         }
 346         r.Logger.Printf("statfs %d available %d used %d total%s\n",
 347                 nextSample.available, nextSample.used, nextSample.total, delta)
 348         r.lastDiskSpaceSample = nextSample
 349 }
 350
 351 type cpuSample struct {
 352         hasData    bool // to distinguish the zero value from real data
 353         sampleTime time.Time
 354         user       float64
 355         sys        float64
 356         cpus       int64
 357 }
 358
 359 // Return the number of CPUs available in the container. Return 0 if
 360 // we can't figure out the real number of CPUs.
 361 func (r *Reporter) getCPUCount() int64 {
 362         cpusetFile, err := r.openStatFile("cpuset", "cpuset.cpus", true)
 363         if err != nil {
 364                 return 0
 365         }
 366         defer cpusetFile.Close()
 367         b, err := r.readAllOrWarn(cpusetFile)
 368         if err != nil {
 369                 return 0
 370         }
 371         sp := strings.Split(string(b), ",")
 372         cpus := int64(0)
 373         for _, v := range sp {
 374                 var min, max int64
 375                 n, _ := fmt.Sscanf(v, "%d-%d", &min, &max)
 376                 if n == 2 {
 377                         cpus += (max - min) + 1
 378                 } else {
 379                         cpus++
 380                 }
 381         }
 382         return cpus
 383 }
 384
 385 func (r *Reporter) doCPUStats() {
 386         statFile, err := r.openStatFile("cpuacct", "cpuacct.stat", true)
 387         if err != nil {
 388                 return
 389         }
 390         defer statFile.Close()
 391         b, err := r.readAllOrWarn(statFile)
 392         if err != nil {
 393                 return
 394         }
 395
 396         var userTicks, sysTicks int64
 397         fmt.Sscanf(string(b), "user %d\nsystem %d", &userTicks, &sysTicks)
 398         userHz := float64(C.sysconf(C._SC_CLK_TCK))
 399         nextSample := cpuSample{
 400                 hasData:    true,
 401                 sampleTime: time.Now(),
 402                 user:       float64(userTicks) / userHz,
 403                 sys:        float64(sysTicks) / userHz,
 404                 cpus:       r.getCPUCount(),
 405         }
 406
 407         delta := ""
 408         if r.lastCPUSample.hasData {
 409                 delta = fmt.Sprintf(" -- interval %.4f seconds %.4f user %.4f sys",
 410                         nextSample.sampleTime.Sub(r.lastCPUSample.sampleTime).Seconds(),
 411                         nextSample.user-r.lastCPUSample.user,
 412                         nextSample.sys-r.lastCPUSample.sys)
 413         }
 414         r.Logger.Printf("cpu %.4f user %.4f sys %d cpus%s\n",
 415                 nextSample.user, nextSample.sys, nextSample.cpus, delta)
 416         r.lastCPUSample = nextSample
 417 }
 418
 419 // Report stats periodically until we learn (via r.done) that someone
 420 // called Stop.
 421 func (r *Reporter) run() {
 422         defer close(r.flushed)
 423
 424         r.reportedStatFile = make(map[string]string)
 425
 426         if !r.waitForCIDFile() || !r.waitForCgroup() {
 427                 return
 428         }
 429
 430         r.lastNetSample = make(map[string]ioSample)
 431         r.lastDiskIOSample = make(map[string]ioSample)
 432
 433         if len(r.TempDir) == 0 {
 434                 // Temporary dir not provided, try to get it from the environment.
 435                 r.TempDir = os.Getenv("TMPDIR")
 436         }
 437         if len(r.TempDir) > 0 {
 438                 r.Logger.Printf("notice: monitoring temp dir %s\n", r.TempDir)
 439         }
 440
 441         ticker := time.NewTicker(r.PollPeriod)
 442         for {
 443                 r.doMemoryStats()
 444                 r.doCPUStats()
 445                 r.doBlkIOStats()
 446                 r.doNetworkStats()
 447                 r.doDiskSpaceStats()
 448                 select {
 449                 case <-r.done:
 450                         return
 451                 case <-ticker.C:
 452                 }
 453         }
 454 }
 455
 456 // If CID is empty, wait for it to appear in CIDFile. Return true if
 457 // we get it before we learn (via r.done) that someone called Stop.
 458 func (r *Reporter) waitForCIDFile() bool {
 459         if r.CID != "" || r.CIDFile == "" {
 460                 return true
 461         }
 462
 463         ticker := time.NewTicker(100 * time.Millisecond)
 464         defer ticker.Stop()
 465         for {
 466                 cid, err := ioutil.ReadFile(r.CIDFile)
 467                 if err == nil && len(cid) > 0 {
 468                         r.CID = string(cid)
 469                         return true
 470                 }
 471                 select {
 472                 case <-ticker.C:
 473                 case <-r.done:
 474                         r.Logger.Printf("warning: CID never appeared in %+q: %v", r.CIDFile, err)
 475                         return false
 476                 }
 477         }
 478 }
 479
 480 // Wait for the cgroup stats files to appear in cgroup_root. Return
 481 // true if they appear before r.done indicates someone called Stop. If
 482 // they don't appear within one poll interval, log a warning and keep
 483 // waiting.
 484 func (r *Reporter) waitForCgroup() bool {
 485         ticker := time.NewTicker(100 * time.Millisecond)
 486         defer ticker.Stop()
 487         warningTimer := time.After(r.PollPeriod)
 488         for {
 489                 c, err := r.openStatFile("cpuacct", "cgroup.procs", false)
 490                 if err == nil {
 491                         c.Close()
 492                         return true
 493                 }
 494                 select {
 495                 case <-ticker.C:
 496                 case <-warningTimer:
 497                         r.Logger.Printf("warning: cgroup stats files have not appeared after %v (config error?) -- still waiting...", r.PollPeriod)
 498                 case <-r.done:
 499                         r.Logger.Printf("warning: cgroup stats files never appeared for %v", r.CID)
 500                         return false
 501                 }
 502         }
 503 }