Scrape CPU latency stats from /proc/schedstat (#1389)

These are useful as a direct indication of CPU contention and task
scheduler latency.

Handy references:
 - https://github.com/torvalds/linux/blob/master/Documentation/scheduler/sched-stats.txt
 - https://doc.opensuse.org/documentation/leap/tuning/html/book.sle.tuning/cha.tuning.taskscheduler.html

procfs is updated to pull in the enabling change:
https://github.com/prometheus/procfs/pull/186

Signed-off-by: Phil Frost <phil@postmates.com>

CHANGELOG.md

@@ -13,7 +13,7 @@
 
 * [CHANGE] Add `--collector.netdev.device-whitelist`. #1279
 * [CHANGE] Refactor mdadm collector #1403
-* [FEATURE]
+* [FEATURE] Add new schedstat collector #1389
 * [ENHANCEMENT]
 * [BUGFIX] Renamed label `state` to `name` on `node_systemd_service_restart_total`. #1393
 

README.md

@@ -51,6 +51,7 @@ netstat | Exposes network statistics from `/proc/net/netstat`. This is the same
 nfs | Exposes NFS client statistics from `/proc/net/rpc/nfs`. This is the same information as `nfsstat -c`. | Linux
 nfsd | Exposes NFS kernel server statistics from `/proc/net/rpc/nfsd`. This is the same information as `nfsstat -s`. | Linux
 pressure | Exposes pressure stall statistics from `/proc/pressure/`. | Linux (kernel 4.20+ and/or [CONFIG\_PSI](https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/accounting/psi.txt))
+schedstat | Exposes task scheduler statistics from `/proc/schedstat`. | Linux
 sockstat | Exposes various statistics from `/proc/net/sockstat`. | Linux
 stat | Exposes various statistics from `/proc/stat`. This includes boot time, forks and interrupts. | Linux
 textfile | Exposes statistics read from local disk. The `--collector.textfile.directory` flag must be set. | _any_

collector/fixtures/e2e-64k-page-output.txt

@@ -2438,6 +2438,18 @@ node_qdisc_packets_total{device="wlan0",kind="fq"} 42
 # TYPE node_qdisc_requeues_total counter
 node_qdisc_requeues_total{device="eth0",kind="pfifo_fast"} 2
 node_qdisc_requeues_total{device="wlan0",kind="fq"} 1
+# HELP node_schedstat_running_seconds_total Number of seconds CPU spent running a process.
+# TYPE node_schedstat_running_seconds_total counter
+node_schedstat_running_seconds_total{cpu="0"} 2.045936778163039e+13
+node_schedstat_running_seconds_total{cpu="1"} 1.904686152592476e+13
+# HELP node_schedstat_timeslices_total Number of timeslices executed by CPU.
+# TYPE node_schedstat_timeslices_total counter
+node_schedstat_timeslices_total{cpu="0"} 4.767485306e+09
+node_schedstat_timeslices_total{cpu="1"} 5.145567945e+09
+# HELP node_schedstat_waiting_seconds_total Number of seconds spent by processing waiting for this CPU.
+# TYPE node_schedstat_waiting_seconds_total counter
+node_schedstat_waiting_seconds_total{cpu="0"} 3.43796328169361e+12
+node_schedstat_waiting_seconds_total{cpu="1"} 3.64107263788241e+12
 # HELP node_scrape_collector_duration_seconds node_exporter: Duration of a collector scrape.
 # TYPE node_scrape_collector_duration_seconds gauge
 # HELP node_scrape_collector_success node_exporter: Whether a collector succeeded.
@@ -2472,6 +2484,7 @@ node_scrape_collector_success{collector="nfsd"} 1
 node_scrape_collector_success{collector="pressure"} 1
 node_scrape_collector_success{collector="processes"} 1
 node_scrape_collector_success{collector="qdisc"} 1
+node_scrape_collector_success{collector="schedstat"} 1
 node_scrape_collector_success{collector="sockstat"} 1
 node_scrape_collector_success{collector="stat"} 1
 node_scrape_collector_success{collector="textfile"} 1

collector/fixtures/e2e-output.txt

@@ -2438,6 +2438,18 @@ node_qdisc_packets_total{device="wlan0",kind="fq"} 42
 # TYPE node_qdisc_requeues_total counter
 node_qdisc_requeues_total{device="eth0",kind="pfifo_fast"} 2
 node_qdisc_requeues_total{device="wlan0",kind="fq"} 1
+# HELP node_schedstat_running_seconds_total Number of seconds CPU spent running a process.
+# TYPE node_schedstat_running_seconds_total counter
+node_schedstat_running_seconds_total{cpu="0"} 2.045936778163039e+13
+node_schedstat_running_seconds_total{cpu="1"} 1.904686152592476e+13
+# HELP node_schedstat_timeslices_total Number of timeslices executed by CPU.
+# TYPE node_schedstat_timeslices_total counter
+node_schedstat_timeslices_total{cpu="0"} 4.767485306e+09
+node_schedstat_timeslices_total{cpu="1"} 5.145567945e+09
+# HELP node_schedstat_waiting_seconds_total Number of seconds spent by processing waiting for this CPU.
+# TYPE node_schedstat_waiting_seconds_total counter
+node_schedstat_waiting_seconds_total{cpu="0"} 3.43796328169361e+12
+node_schedstat_waiting_seconds_total{cpu="1"} 3.64107263788241e+12
 # HELP node_scrape_collector_duration_seconds node_exporter: Duration of a collector scrape.
 # TYPE node_scrape_collector_duration_seconds gauge
 # HELP node_scrape_collector_success node_exporter: Whether a collector succeeded.
@@ -2472,6 +2484,7 @@ node_scrape_collector_success{collector="nfsd"} 1
 node_scrape_collector_success{collector="pressure"} 1
 node_scrape_collector_success{collector="processes"} 1
 node_scrape_collector_success{collector="qdisc"} 1
+node_scrape_collector_success{collector="schedstat"} 1
 node_scrape_collector_success{collector="sockstat"} 1
 node_scrape_collector_success{collector="stat"} 1
 node_scrape_collector_success{collector="textfile"} 1

collector/fixtures/proc/schedstat

@@ -0,0 +1,6 @@
+version 15
+timestamp 15819019232
+cpu0 498494191 0 3533438552 2553969831 3853684107 2465731542 2045936778163039 343796328169361 4767485306
+domain0 00000000,00000003 212499247 210112015 1861015 1860405436 536440 369895 32599 210079416 25368550 24241256 384652 927363878 807233 6366 1647 24239609 2122447165 1886868564 121112060 2848625533 125678146 241025 1032026 1885836538 2545 12 2533 0 0 0 0 0 0 1387952561 21076581 0
+cpu1 518377256 0 4155211005 2778589869 10466382 2867629021 1904686152592476 364107263788241 5145567945
+domain0 00000000,00000003 217653037 215526982 1577949 1580427380 557469 393576 28538 215498444 28721913 27662819 371153 870843407 745912 5523 1639 27661180 2331056874 2107732788 111442342 652402556 123615235 196159 1045245 2106687543 2400 3 2397 0 0 0 0 0 0 1437804657 26220076 0

collector/schedstat_linux.go

@@ -0,0 +1,94 @@
+// Copyright 2019 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package collector
+
+import (
+	"fmt"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/procfs"
+)
+
+var (
+	runningSecondsTotal = prometheus.NewDesc(
+		prometheus.BuildFQName(namespace, "schedstat", "running_seconds_total"),
+		"Number of seconds CPU spent running a process.",
+		[]string{"cpu"},
+		nil,
+	)
+
+	waitingSecondsTotal = prometheus.NewDesc(
+		prometheus.BuildFQName(namespace, "schedstat", "waiting_seconds_total"),
+		"Number of seconds spent by processing waiting for this CPU.",
+		[]string{"cpu"},
+		nil,
+	)
+
+	timeslicesTotal = prometheus.NewDesc(
+		prometheus.BuildFQName(namespace, "schedstat", "timeslices_total"),
+		"Number of timeslices executed by CPU.",
+		[]string{"cpu"},
+		nil,
+	)
+)
+
+// NewSchedstatCollector returns a new Collector exposing task scheduler statistics
+func NewSchedstatCollector() (Collector, error) {
+	fs, err := procfs.NewFS(*procPath)
+	if err != nil {
+		return nil, fmt.Errorf("failed to open procfs: %v", err)
+	}
+
+	return &schedstatCollector{fs: fs}, nil
+}
+
+type schedstatCollector struct {
+	fs procfs.FS
+}
+
+func init() {
+	registerCollector("schedstat", defaultEnabled, NewSchedstatCollector)
+}
+
+func (c *schedstatCollector) Update(ch chan<- prometheus.Metric) error {
+	stats, err := c.fs.Schedstat()
+	if err != nil {
+		return err
+	}
+
+	for _, cpu := range stats.CPUs {
+		ch <- prometheus.MustNewConstMetric(
+			runningSecondsTotal,
+			prometheus.CounterValue,
+			cpu.RunningSeconds(),
+			cpu.CPUNum,
+		)
+
+		ch <- prometheus.MustNewConstMetric(
+			waitingSecondsTotal,
+			prometheus.CounterValue,
+			cpu.WaitingSeconds(),
+			cpu.CPUNum,
+		)
+
+		ch <- prometheus.MustNewConstMetric(
+			timeslicesTotal,
+			prometheus.CounterValue,
+			float64(cpu.RunTimeslices),
+			cpu.CPUNum,
+		)
+	}
+
+	return nil
+}

end-to-end-test.sh

@@ -30,6 +30,7 @@ enabled_collectors=$(cat << COLLECTORS
   nfsd
   pressure
   qdisc
+  schedstat
   sockstat
   stat
   textfile

go.mod

@@ -15,7 +15,7 @@ require (
 	github.com/prometheus/client_golang v1.0.0
 	github.com/prometheus/client_model v0.0.0-20190129233127-fd36f4220a90
 	github.com/prometheus/common v0.4.1
-	github.com/prometheus/procfs v0.0.4-0.20190627154503-39e1aff1547e
+	github.com/prometheus/procfs v0.0.4-0.20190702183519-8f55e607908e
 	github.com/siebenmann/go-kstat v0.0.0-20160321171754-d34789b79745
 	github.com/sirupsen/logrus v1.4.2 // indirect
 	github.com/soundcloud/go-runit v0.0.0-20150630195641-06ad41a06c4a

go.sum

@@ -68,8 +68,8 @@ github.com/prometheus/common v0.4.1/go.mod h1:TNfzLD0ON7rHzMJeJkieUDPYmFC7Snx/y8
 github.com/prometheus/procfs v0.0.0-20181005140218-185b4288413d/go.mod h1:c3At6R/oaqEKCNdg8wHV1ftS6bRYblBhIjjI8uT2IGk=
 github.com/prometheus/procfs v0.0.2 h1:6LJUbpNm42llc4HRCuvApCSWB/WfhuNo9K98Q9sNGfs=
 github.com/prometheus/procfs v0.0.2/go.mod h1:TjEm7ze935MbeOT/UhFTIMYKhuLP4wbCsTZCD3I8kEA=
-github.com/prometheus/procfs v0.0.4-0.20190627154503-39e1aff1547e h1:wHo3spLBVUEsk0etFRCYPI6CpKUZnxq0JwqXjaQhp/g=
+github.com/prometheus/procfs v0.0.4-0.20190702183519-8f55e607908e h1:p57e/ejwNofSHhEh+d7KoCVpHSTN3efX5Aj3z0jGWIE=
-github.com/prometheus/procfs v0.0.4-0.20190627154503-39e1aff1547e/go.mod h1:4A/X28fw3Fc593LaREMrKMqOKvUAntwMDaekg4FpcdQ=
+github.com/prometheus/procfs v0.0.4-0.20190702183519-8f55e607908e/go.mod h1:4A/X28fw3Fc593LaREMrKMqOKvUAntwMDaekg4FpcdQ=
 github.com/siebenmann/go-kstat v0.0.0-20160321171754-d34789b79745 h1:IuH7WumZNax0D+rEqmy2TyhKCzrtMGqbZO0b8rO00JA=
 github.com/siebenmann/go-kstat v0.0.0-20160321171754-d34789b79745/go.mod h1:G81aIFAMS9ECrwBYR9YxhlPjWgrItd+Kje78O6+uqm8=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=

vendor/github.com/prometheus/procfs/fixtures.ttar

@@ -168,6 +168,11 @@ SymlinkTo: net:[4026531993]
 Path: fixtures/proc/26231/root
 SymlinkTo: /
 # ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
+Path: fixtures/proc/26231/schedstat
+Lines: 1
+411605849 93680043 79
+Mode: 644
+# ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
 Path: fixtures/proc/26231/stat
 Lines: 1
 26231 (vim) R 5392 7446 5392 34835 7446 4218880 32533 309516 26 82 1677 44 158 99 20 0 1 0 82375 56274944 1981 18446744073709551615 4194304 6294284 140736914091744 140736914087944 139965136429984 0 0 12288 1870679807 0 0 0 17 0 0 0 31 0 0 8391624 8481048 16420864 140736914093252 140736914093279 140736914093279 140736914096107 0
@@ -300,6 +305,18 @@ Lines: 1
 com.github.uiautomatorNULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTENULLBYTEEOF
 Mode: 644
 # ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
+Path: fixtures/proc/26233/schedstat
+Lines: 8
+ ____________________________________
+< this is a malformed schedstat file >
+ ------------------------------------
+        \   ^__^
+         \  (oo)\_______
+            (__)\       )\/\
+                ||----w |
+                ||     ||
+Mode: 644
+# ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
 Directory: fixtures/proc/584
 Mode: 755
 # ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
@@ -609,6 +626,16 @@ some avg10=0.10 avg60=2.00 avg300=3.85 total=15
 full avg10=0.20 avg60=3.00 avg300=4.95 total=25
 Mode: 644
 # ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
+Path: fixtures/proc/schedstat
+Lines: 6
+version 15
+timestamp 15819019232
+cpu0 498494191 0 3533438552 2553969831 3853684107 2465731542 2045936778163039 343796328169361 4767485306
+domain0 00000000,00000003 212499247 210112015 1861015 1860405436 536440 369895 32599 210079416 25368550 24241256 384652 927363878 807233 6366 1647 24239609 2122447165 1886868564 121112060 2848625533 125678146 241025 1032026 1885836538 2545 12 2533 0 0 0 0 0 0 1387952561 21076581 0
+cpu1 518377256 0 4155211005 2778589869 10466382 2867629021 1904686152592476 364107263788241 5145567945
+domain0 00000000,00000003 217653037 215526982 1577949 1580427380 557469 393576 28538 215498444 28721913 27662819 371153 870843407 745912 5523 1639 27661180 2331056874 2107732788 111442342 652402556 123615235 196159 1045245 2106687543 2400 3 2397 0 0 0 0 0 0 1437804657 26220076 0
+Mode: 644
+# ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
 Path: fixtures/proc/self
 SymlinkTo: 26231
 # ttar - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

vendor/github.com/prometheus/procfs/proc.go

@@ -300,3 +300,12 @@ func (p Proc) FileDescriptorsInfo() (ProcFDInfos, error) {
 
 	return fdinfos, nil
 }
+
+// Schedstat returns task scheduling information for the process.
+func (p Proc) Schedstat() (ProcSchedstat, error) {
+	contents, err := ioutil.ReadFile(p.path("schedstat"))
+	if err != nil {
+		return ProcSchedstat{}, err
+	}
+	return parseProcSchedstat(string(contents))
+}

vendor/github.com/prometheus/procfs/schedstat.go

@@ -0,0 +1,128 @@
+// Copyright 2019 The Prometheus Authors
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package procfs
+
+import (
+	"bufio"
+	"errors"
+	"os"
+	"regexp"
+	"strconv"
+)
+
+var (
+	cpuLineRE  = regexp.MustCompile(`cpu(\d+) (\d+) (\d+) (\d+) (\d+) (\d+) (\d+) (\d+) (\d+) (\d+)`)
+	procLineRE = regexp.MustCompile(`(\d+) (\d+) (\d+)`)
+)
+
+// Schedstat contains scheduler statistics from /proc/schedstats
+//
+// See
+// https://www.kernel.org/doc/Documentation/scheduler/sched-stats.txt
+// for a detailed description of what these numbers mean.
+type Schedstat struct {
+	CPUs []*SchedstatCPU
+}
+
+// SchedstatCPU contains the values from one "cpu<N>" line
+type SchedstatCPU struct {
+	CPUNum string
+
+	RunningJiffies uint64
+	WaitingJiffies uint64
+	RunTimeslices  uint64
+}
+
+// ProcSchedstat contains the values from /proc/<pid>/schedstat
+type ProcSchedstat struct {
+	RunningJiffies uint64
+	WaitingJiffies uint64
+	RunTimeslices  uint64
+}
+
+func (fs FS) Schedstat() (*Schedstat, error) {
+	file, err := os.Open(fs.proc.Path("schedstat"))
+	if err != nil {
+		return nil, err
+	}
+	defer file.Close()
+
+	stats := &Schedstat{}
+	scanner := bufio.NewScanner(file)
+
+	for scanner.Scan() {
+		match := cpuLineRE.FindStringSubmatch(scanner.Text())
+		if match != nil {
+			cpu := &SchedstatCPU{}
+			cpu.CPUNum = match[1]
+
+			cpu.RunningJiffies, err = strconv.ParseUint(match[8], 10, 64)
+			if err != nil {
+				continue
+			}
+
+			cpu.WaitingJiffies, err = strconv.ParseUint(match[9], 10, 64)
+			if err != nil {
+				continue
+			}
+
+			cpu.RunTimeslices, err = strconv.ParseUint(match[10], 10, 64)
+			if err != nil {
+				continue
+			}
+
+			stats.CPUs = append(stats.CPUs, cpu)
+		}
+	}
+
+	return stats, nil
+}
+
+func parseProcSchedstat(contents string) (stats ProcSchedstat, err error) {
+	match := procLineRE.FindStringSubmatch(contents)
+
+	if match != nil {
+		stats.RunningJiffies, err = strconv.ParseUint(match[1], 10, 64)
+		if err != nil {
+			return
+		}
+
+		stats.WaitingJiffies, err = strconv.ParseUint(match[2], 10, 64)
+		if err != nil {
+			return
+		}
+
+		stats.RunTimeslices, err = strconv.ParseUint(match[3], 10, 64)
+		return
+	}
+
+	err = errors.New("could not parse schedstat")
+	return
+}
+
+func (stat *SchedstatCPU) RunningSeconds() float64 {
+	return float64(stat.RunningJiffies) / userHZ
+}
+
+func (stat *SchedstatCPU) WaitingSeconds() float64 {
+	return float64(stat.WaitingJiffies) / userHZ
+}
+
+func (stat *ProcSchedstat) RunningSeconds() float64 {
+	return float64(stat.RunningJiffies) / userHZ
+}
+
+func (stat *ProcSchedstat) WaitingSeconds() float64 {
+	return float64(stat.WaitingJiffies) / userHZ
+}

vendor/modules.txt

@@ -45,7 +45,7 @@ github.com/prometheus/common/version
 github.com/prometheus/common/expfmt
 github.com/prometheus/common/model
 github.com/prometheus/common/internal/bitbucket.org/ww/goautoneg
-# github.com/prometheus/procfs v0.0.4-0.20190627154503-39e1aff1547e
+# github.com/prometheus/procfs v0.0.4-0.20190702183519-8f55e607908e
 github.com/prometheus/procfs
 github.com/prometheus/procfs/bcache
 github.com/prometheus/procfs/nfs