Project

General

Profile

Bug #10288

race in cpustat(1) results in dropped output

Added by Robert Mustacchi 11 months ago. Updated 10 months ago.

Status:
Closed
Priority:
Normal
Category:
cmd - userland programs
Start date:
2019-01-24
Due date:
% Done:

100%

Estimated time:
Difficulty:
Medium
Tags:

Description

When run and redirecting to a file, cpustat will occasionally drop output for a particular CPU. Take this script:

#!/usr/bin/bash

cpustat=`which cpustat`

let i=0

while [[ $i -lt 100 ]]; do
    out=cpustat.out.$i
    $cpustat -c pic0=inst_retired.any_p 0.01 100 > $out
    wc -l $out
    let i=i+1
done

Running this should always yield the same output – and the number of lines should always be the number of CPUs times one hundred, plus two (one header line, one summary line). However, running this yields output over a surprising span, e.g., on a physical machine with 5 logical CPUs available (not in a processor set):

[root@haswell /var/tmp]# wc -l cpustat.out.* | grep cpustat  | awk '{ print $1 }' | sort | uniq -c
   2 498
   5 499
  13 500
  30 501
  50 502

Looking at (say) one of the 498 line output:

[root@haswell /var/tmp]# cat cpustat.out.69 | grep -v cpu | grep -v total | awk '{ print $2 }' | sort | uniq -c | sort -n
  98 1
  99 0
  99 2
 100 4
 100 5

This says that CPU 1 appeared 98 times, while CPU 5 has appeared 100 times in the output. This is just wrong – and it's because the threads themselves are racing to write:

[root@haswell /var/tmp]# dtrace -n syscall::write:entry'/pid == $target/{@[tid] = count()}' -n END'{freopen("/dev/fd/2")}' -w -c "cpustat -c pic0=inst_retired.any_p 0.01 100" > /dev/null
dtrace: description 'syscall::write:entry' matched 1 probe
dtrace: description 'END' matched 1 probe
dtrace: allowing destructive actions
dtrace: pid 8370 has exited

        1                2
        2              100
        3              100
        4              100
        5              100
        6              100

The threads are racing here:

[root@haswell /var/tmp]# dtrace -n syscall::write:entry'/pid == $target && tid != 1/{@[ustack()] = count()}' -n END'{freopen("/dev/fd/2")}' -w -c "cpustat -c pic0=inst_retired.any_p 0.01 100" > /dev/null
dtrace: description 'syscall::write:entry' matched 1 probe
dtrace: description 'END' matched 1 probe
dtrace: allowing destructive actions
dtrace: pid 8372 has exited

              libc.so.1`__write+0x15
              cpustat`print_sample+0x206
              cpustat`gtick+0x2b3
              libc.so.1`_thrp_setup+0x88
              libc.so.1`_lwp_start
              500

Ultimately, print_sample is boiling down a CPU's worth of output for a unit of time to a single write – but if stdout is not open O_APPEND (as it won't be if output is redirected to a file), one write can effectively plow another.

History

#1

Updated by Electric Monk 10 months ago

  • Status changed from New to Closed

git commit 09d80cead6ef4d1a3a186dd195dd0de1ccb19aaa

commit  09d80cead6ef4d1a3a186dd195dd0de1ccb19aaa
Author: Bryan Cantrill <bryan@joyent.com>
Date:   2019-01-28T22:42:45.000Z

    10288 race in cpustat(1) results in dropped output
    Reviewed by: Robert Mustacchi <rm@joyent.com>
    Reviewed by: Joshua M. Clulow <jmc@joyent.com>
    Reviewed by: Rob Johnston <rob.johnston@joyent.com>
    Reviewed by: Andy Fiddaman <af@citrus-it.net>
    Approved by: Dan McDonald <danmcd@joyent.com>

Also available in: Atom PDF