From f693a71c0648ae9dd28f7991ca845afe12539a37 Mon Sep 17 00:00:00 2001 From: Phil Frost Date: Wed, 10 Jul 2019 03:16:24 -0400 Subject: [PATCH] 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 --- CHANGELOG.md | 2 +- README.md | 1 + collector/fixtures/e2e-64k-page-output.txt | 13 ++ collector/fixtures/e2e-output.txt | 13 ++ collector/fixtures/proc/schedstat | 6 + collector/schedstat_linux.go | 94 +++++++++++++ end-to-end-test.sh | 1 + go.mod | 2 +- go.sum | 4 +- .../prometheus/procfs/fixtures.ttar | 27 ++++ vendor/github.com/prometheus/procfs/proc.go | 9 ++ .../github.com/prometheus/procfs/schedstat.go | 128 ++++++++++++++++++ vendor/modules.txt | 2 +- 13 files changed, 297 insertions(+), 5 deletions(-) create mode 100644 collector/fixtures/proc/schedstat create mode 100644 collector/schedstat_linux.go create mode 100644 vendor/github.com/prometheus/procfs/schedstat.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 21599c0b..9e776210 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/README.md b/README.md index b73c8af6..795ab609 100644 --- a/README.md +++ b/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_ diff --git a/collector/fixtures/e2e-64k-page-output.txt b/collector/fixtures/e2e-64k-page-output.txt index b7cf4372..7f503c86 100644 --- a/collector/fixtures/e2e-64k-page-output.txt +++ b/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 diff --git a/collector/fixtures/e2e-output.txt b/collector/fixtures/e2e-output.txt index 3f5292c4..b3f750a0 100644 --- a/collector/fixtures/e2e-output.txt +++ b/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 diff --git a/collector/fixtures/proc/schedstat b/collector/fixtures/proc/schedstat new file mode 100644 index 00000000..5a555c00 --- /dev/null +++ b/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 diff --git a/collector/schedstat_linux.go b/collector/schedstat_linux.go new file mode 100644 index 00000000..5e7638a8 --- /dev/null +++ b/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 +} diff --git a/end-to-end-test.sh b/end-to-end-test.sh index 6d3c9f44..56ed04c8 100755 --- a/end-to-end-test.sh +++ b/end-to-end-test.sh @@ -30,6 +30,7 @@ enabled_collectors=$(cat << COLLECTORS nfsd pressure qdisc + schedstat sockstat stat textfile diff --git a/go.mod b/go.mod index 7205d643..5a9ef7b6 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 66d56e4e..73eeda29 100644 --- a/go.sum +++ b/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.20190627154503-39e1aff1547e/go.mod h1:4A/X28fw3Fc593LaREMrKMqOKvUAntwMDaekg4FpcdQ= +github.com/prometheus/procfs v0.0.4-0.20190702183519-8f55e607908e h1:p57e/ejwNofSHhEh+d7KoCVpHSTN3efX5Aj3z0jGWIE= +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= diff --git a/vendor/github.com/prometheus/procfs/fixtures.ttar b/vendor/github.com/prometheus/procfs/fixtures.ttar index 8ebd5b97..b7437448 100644 --- a/vendor/github.com/prometheus/procfs/fixtures.ttar +++ b/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 - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - diff --git a/vendor/github.com/prometheus/procfs/proc.go b/vendor/github.com/prometheus/procfs/proc.go index a0aee595..b7c79cf7 100644 --- a/vendor/github.com/prometheus/procfs/proc.go +++ b/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)) +} diff --git a/vendor/github.com/prometheus/procfs/schedstat.go b/vendor/github.com/prometheus/procfs/schedstat.go new file mode 100644 index 00000000..86396c0d --- /dev/null +++ b/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" line +type SchedstatCPU struct { + CPUNum string + + RunningJiffies uint64 + WaitingJiffies uint64 + RunTimeslices uint64 +} + +// ProcSchedstat contains the values from /proc//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 +} diff --git a/vendor/modules.txt b/vendor/modules.txt index 0c0cde44..8aba662a 100644 --- a/vendor/modules.txt +++ b/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