Demonstrations of cpuunclaimed, the Linux eBPF/bcc version.

This tool samples the length of the CPU run queues and determine when there are

idle CPUs, yet queued threads waiting their turn. It reports the amount of idle

(yet unclaimed by waiting threads) CPU as a system-wide percentage. For

example:

# ./cpuunclaimed.py

Sampling run queues... Output every 1 seconds. Hit Ctrl-C to end.

%CPU 83.00%, unclaimed idle 0.12%

%CPU 87.25%, unclaimed idle 0.38%

%CPU 85.00%, unclaimed idle 0.25%

%CPU 85.00%, unclaimed idle 0.25%

%CPU 80.88%, unclaimed idle 0.00%

%CPU 82.25%, unclaimed idle 0.00%

%CPU 83.50%, unclaimed idle 0.12%

%CPU 81.50%, unclaimed idle 0.00%

%CPU 81.38%, unclaimed idle 0.00%

[...]

This shows a system running at over 80% CPU utilization, and with less than

0.5% unclaimed idle CPUs.

Unclaimed idle CPUs can happen for a number of reasons:

- An application has been bound to some, but not all, CPUs, and has runnable

threads that cannot migrate to other CPUs due to this configuration.

- CPU affinity: an optimization that leaves threads on CPUs where the CPU

caches are warm, even if this means short periods of waiting while other

CPUs are idle. The wait period is tunale (see sysctl, kernel.sched*).

- Scheduler bugs.

An unclaimed idle of < 1% is likely to be CPU affinity, and not usually a

cause for concern. By leaving the CPU idle, overall throughput of the system

may be improved. This tool is best for identifying larger issues, > 2%, due

to the coarseness of its 99 Hertz samples.

This is an 8 CPU system, with an 8 CPU-bound threaded application running that

has been bound to one CPU (via taskset):

# ./cpuunclaimed.py

Sampling run queues... Output every 1 seconds. Hit Ctrl-C to end.

%CPU 12.63%, unclaimed idle 86.36%

%CPU 12.50%, unclaimed idle 87.50%

%CPU 12.63%, unclaimed idle 87.37%

%CPU 12.75%, unclaimed idle 87.25%

%CPU 12.50%, unclaimed idle 87.50%

%CPU 12.63%, unclaimed idle 87.37%

%CPU 12.50%, unclaimed idle 87.50%

%CPU 12.50%, unclaimed idle 87.50%

[...]

It shows that 7 of the 8 CPUs (87.5%) are idle at the same time there are

queued threads waiting to run on CPU. This is an artificial situation caused

by binding threads to the same CPU, to demonstrate how the tool works.

This is an 8 CPU system running a Linux kernel build with "make -j8", and -T

to print timestamps:

# ./cpuunclaimed.py -T

Sampling run queues... Output every 1 seconds. Hit Ctrl-C to end.

22:25:55 %CPU 98.88%, unclaimed idle 0.12%

22:25:56 %CPU 99.75%, unclaimed idle 0.25%

22:25:57 %CPU 99.50%, unclaimed idle 0.50%

22:25:58 %CPU 99.25%, unclaimed idle 0.75%

22:25:59 %CPU 99.75%, unclaimed idle 0.25%

22:26:00 %CPU 99.50%, unclaimed idle 0.50%

22:26:01 %CPU 99.25%, unclaimed idle 0.75%

22:26:02 %CPU 99.25%, unclaimed idle 0.75%

22:26:03 %CPU 99.01%, unclaimed idle 0.87%

22:26:04 %CPU 99.88%, unclaimed idle 0.12%

22:26:05 %CPU 99.38%, unclaimed idle 0.62%

There's now a consistent, yet small, amount of unclaimed idle CPU. This is

expected to be deliberate: CPU affinity, as mentioned earlier.

The -j option will print raw samples: around one hundred lines of output

every second. For the same system with a Linux kernel build of "make -j8":

# ./cpuunclaimed.py -j

TIMESTAMP_ns,CPU0,CPU1,CPU2,CPU3,CPU4,CPU5,CPU6,CPU7

514606928954752,1,1,1,1,1,1,1,1

514606939054312,1,1,1,1,1,1,1,2

514606949156518,1,1,1,1,1,1,1,1

514606959256596,2,2,1,1,1,1,1,1

514606969357989,1,1,1,1,1,2,1,1

514606979459700,1,2,1,1,1,2,1,1

514606989560481,1,1,1,1,1,1,1,1

514606999661396,1,1,1,1,1,1,2,1

514607009795601,1,1,1,1,1,1,1,2

514607019862711,1,1,1,1,1,1,1,1

514607029963734,1,1,1,1,1,1,1,1

514607040062372,1,1,1,1,1,1,1,1

514607050197735,1,1,1,2,1,1,1,1

514607060266464,1,1,1,1,1,1,1,2

514607070368025,1,1,1,1,1,2,1,1

514607080468375,1,1,1,1,1,1,1,2

514607090570292,3,2,1,1,1,1,1,1

514607100670725,1,1,1,1,1,2,1,1

514607110771946,1,2,1,1,1,1,1,1

514607120873489,1,1,1,1,2,1,2,1

514607130973857,2,1,1,1,3,1,1,1

514607141080056,0,1,1,1,1,2,1,3

514607151176312,1,1,1,2,1,1,1,1

514607161277753,1,1,1,1,1,1,2,1

514607171379095,1,1,1,1,1,1,1,1

514607181479262,1,1,1,1,1,1,1,1

514607191580794,3,1,1,1,1,1,1,1

514607201680952,1,1,1,1,1,1,2,1

514607211783683,1,1,1,1,1,1,1,1

514607221883274,1,1,1,1,1,1,0,1

514607231984244,1,1,1,1,1,1,1,1

514607242085698,1,1,1,1,1,1,1,1

514607252216898,1,2,1,1,1,1,1,1

514607262289420,1,1,1,1,1,2,1,1

514607272389922,1,1,1,1,1,1,1,1

514607282489413,1,1,1,1,1,1,1,1

514607292589950,1,3,1,1,1,1,1,1

514607302693367,1,1,1,1,2,1,1,1

514607312793792,1,1,1,1,1,1,1,1

514607322895249,1,1,1,3,1,1,3,1

514607332994278,1,0,1,1,1,2,1,2

514607343095836,1,1,1,1,1,2,1,1

514607353196533,1,1,1,1,2,1,1,1

514607363297749,1,1,1,1,1,1,1,2

514607373399011,1,1,1,1,1,1,1,2

514607383499730,1,1,1,1,1,1,1,2

514607393601510,1,1,1,1,1,1,1,2

514607403704117,2,1,1,1,1,1,1,2

514607413802700,1,1,1,1,2,1,0,1

514607423904559,1,1,1,1,1,1,1,1

[...]

The output is verbose: printing out a timestamp, and then the length of each

CPU's run queue. The second last line, of timestamp 514607413802700, is an

example of what this tool detects: CPU 4 has a run queue length of 4, which

means one thread running and one thread queued, while CPU 6 has a run queue

length of 0: idle. The very next sample shows all CPUs busy.

The -J option prints raw samples with time offsets showing when the samples

were collected on each CPU. It's mostly useful for debugging the tool itself.

For example, during a Linux kernel build:

# ./cpuunclaimed.py -J

TIMESTAMP_ns,CPU0,CPU1,CPU2,CPU3,CPU4,CPU5,CPU6,CPU7,OFFSET_ns_CPU0,OFFSET_ns_CPU1,OFFSET_ns_CPU2,OFFSET_ns_CPU3,OFFSET_ns_CPU4,OFFSET_ns_CPU5,OFFSET_ns_CPU6,OFFSET_ns_CPU7

514722625198188,1,1,1,1,1,1,1,2,0,28321,51655,73396,89654,111172,132803,159792

514722635299034,1,1,1,1,1,2,1,1,0,28809,51999,74183,89552,110011,131995,153519

514722645400274,1,1,1,1,1,1,1,2,0,28024,51333,73652,88964,110075,131973,153568

514722655501816,1,2,1,1,1,1,1,1,0,28893,51671,75233,89496,109430,131945,153694

514722665602594,1,1,2,1,1,2,1,1,0,28623,50988,73866,89383,109186,131786,154555

514722675703498,1,1,1,1,1,1,1,1,0,27379,51031,73175,89625,110380,131482,104811

514722685804942,1,1,1,1,1,2,1,1,0,27213,50501,72183,88797,108780,130659,152153

514722695906294,1,1,1,1,1,1,1,1,0,27036,51182,73420,87861,109585,130364,155089

514722706005778,1,1,1,1,1,1,1,1,0,28492,51851,74138,89744,110208,132462,154060

514722716060705,1,1,1,1,1,1,1,1,0,154499,152528,155232,155046,154502,178746,200001

514722726209615,1,1,1,1,1,1,1,1,0,28170,49580,72605,87741,108144,130723,152138

514722736309475,1,2,1,1,1,1,1,1,0,27421,51386,73061,89358,109457,131273,153005

514722746410845,1,2,1,1,1,2,1,1,0,27788,50840,72720,88920,109111,131143,152979

514722756511363,1,1,1,1,1,1,2,1,0,28280,50977,73559,89848,109659,131579,152693

514722766613044,1,1,1,1,1,1,1,1,0,28046,50812,72754,89160,110108,130735,152948

514722776712932,1,1,1,2,1,1,1,1,0,28586,51177,73974,89588,109947,132376,154162

514722786815477,1,1,1,1,1,1,1,1,0,27973,71104,72539,88302,108896,130414,152236

514722796914955,1,1,1,1,1,1,1,1,0,29054,52354,74214,89592,110615,132586,153925

514722807044060,1,1,1,1,1,1,1,1,1587130,0,24079,46633,61787,82325,104706,125278

514722817117432,2,1,2,1,1,1,1,1,0,27628,51038,75138,89724,109340,132426,155348

514722827218254,1,1,1,1,1,1,2,1,0,29111,51868,74347,88904,109911,132764,153851

514722837340158,1,1,1,1,1,1,1,1,0,7366,30760,53528,68622,89317,111095,132319

514722847421305,1,1,1,1,1,1,1,1,0,28257,51105,73841,89037,110820,131605,153368

514722857521112,1,1,1,1,1,1,1,1,0,28544,51441,73857,89530,110497,131915,153513

514722867626129,0,2,1,1,1,1,1,1,0,24621,47917,70568,85391,106670,128081,150329

514722877727183,2,1,1,1,1,1,1,1,0,24869,47630,71547,84761,106048,128444,149285

514722887824589,1,1,1,1,1,1,2,1,0,28793,51212,73863,89584,109773,132348,153194

514722897925481,1,1,1,1,1,1,2,1,0,29278,51163,73961,89774,109592,132029,153715

514722908026097,1,1,1,1,1,1,1,1,0,30630,35595,36210,188001,190815,190072,190732

514722918127439,1,1,1,1,1,1,1,1,0,28544,51885,73948,89987,109763,132632,154083

514722928227399,1,1,1,1,1,1,1,1,0,31882,51574,74769,89939,110578,132951,154356

514722938329471,1,1,1,1,1,1,1,1,0,28498,51304,74101,89670,110278,132653,153176

514722948430589,1,1,1,1,1,1,1,1,0,27868,50925,73477,89676,109583,132360,153014

514722958531802,1,1,1,1,1,1,1,1,0,28505,50886,73729,89919,109618,131988,152896

514722968632181,1,1,1,1,1,1,1,1,0,28492,51749,73977,90334,109816,132897,152890

514722978733584,1,1,1,1,1,1,1,1,0,28847,50957,74121,90014,110019,132377,152978

514722988834321,1,1,1,1,1,1,1,1,0,28601,51437,74021,89968,110252,132233,153623

514722998937170,1,1,2,1,1,1,1,1,0,27007,50044,73259,87725,108663,132194,152459

514723009036821,1,2,1,2,1,1,1,1,0,28226,50937,73983,89110,110476,131740,153663

514723019137577,1,1,1,1,1,1,1,1,0,30261,52357,75657,87803,61823,131850,153585

514723029238745,1,1,1,1,1,1,1,1,0,28030,50752,74452,89240,110791,132187,153327

514723039339069,1,1,1,1,1,1,1,1,0,29791,52636,75996,90475,110414,132232,154714

514723049439822,1,1,1,1,2,1,1,1,0,29133,56662,74153,89520,110683,132740,154708

514723059541617,1,1,1,1,1,1,1,1,0,27932,51480,74644,89656,109176,131499,153732

514723069642500,1,1,2,1,1,1,2,1,0,27678,51509,73984,90136,110124,131554,153459

514723079743525,2,1,1,1,1,1,1,1,0,28029,51424,74394,90056,110087,132383,152963

514723089844091,2,1,1,2,1,1,1,1,0,28944,51692,74440,90339,110402,132722,154083

514723099945957,1,1,2,1,1,1,1,1,0,28425,51267,73164,89322,115048,114630,115187

514723110047020,1,1,2,0,1,1,1,2,0,28192,50811,76814,89835,109370,131265,153511

514723120216662,1,1,2,1,1,2,1,1,29,34,0,4514,19268,40293,62674,84009

[...]

This is a Xen guest system, and it shows that CPU 0 usually completes first (an

offset of 0), followed by CPU 1 around 28000 nanoseconds later, and so on.

The spread of offsets is triggered by the bcc Python library that initializes

the timers, which steps through the CPUs in sequence, with a small delay

between them merely from executing its own loop code.

Here's more output during a Linux kernel build:

# ./cpuunclaimed.py -J

TIMESTAMP_ns,CPU0,CPU1,CPU2,CPU3,CPU4,CPU5,CPU6,CPU7,OFFSET_ns_CPU0,OFFSET_ns_CPU1,OFFSET_ns_CPU2,OFFSET_ns_CPU3,OFFSET_ns_CPU4,OFFSET_ns_CPU5,OFFSET_ns_CPU6,OFFSET_ns_CPU7

514722625198188,1,1,1,1,1,1,1,2,0,28321,51655,73396,89654,111172,132803,159792

515700745758947,2,1,1,1,1,1,1,1,0,19835,34891,49397,59364,71988,87571,102769

515700755860451,2,1,1,1,1,1,1,2,0,19946,34323,49855,59844,72741,87925,102891

515700765960560,1,1,1,1,1,1,1,1,0,20805,35339,50436,59677,73557,88661,104796

515700776061744,1,1,1,1,1,1,1,1,1626,77,0,190,153452,154665,178218,154116

515700786162017,1,1,1,1,1,1,1,1,0,20497,35361,51552,59787,74451,147789,104545

515700796262811,1,1,1,1,1,1,1,2,0,20910,35657,50805,60175,73953,88492,103527

515700806364951,1,1,1,1,1,1,1,1,0,20140,35023,50074,59726,72757,88040,102421

515700816465253,1,1,1,1,1,1,2,1,0,20952,34899,50262,60048,72890,88067,103545

515700826566573,1,1,1,1,1,1,1,1,0,20898,35490,50609,59805,74060,88550,103354

515700836667480,1,1,1,1,1,1,2,1,0,20548,34760,50959,59490,73059,87820,103006

515700846768182,1,1,1,1,1,1,2,1,0,20571,35113,50777,59962,74139,88543,103192

515700856869468,1,1,2,1,1,2,2,1,0,20932,35382,50510,60106,73739,91818,103684

515700866971905,1,1,1,2,1,1,1,1,0,19780,33018,49075,58375,71949,86537,102136

515700877073459,2,1,1,1,1,1,1,1,0,20065,73966,48989,58832,71408,85714,101067

515700887172772,1,1,1,1,1,1,1,1,0,20909,34608,51493,59890,73564,88668,103454

515700897273292,1,2,1,1,1,1,1,1,0,20353,35292,50114,59773,73948,88615,103383

515700907374341,1,1,2,1,1,1,1,1,0,20816,35206,50915,60062,73878,88857,103794

515700917475331,1,1,6,1,1,2,1,1,0,20752,34931,50280,59764,73781,88329,103234

515700927576958,1,1,1,1,1,1,1,1,0,19929,34703,50181,59364,73004,88053,103127

515700937677298,1,1,2,2,1,1,1,1,0,21178,34724,50740,61193,73452,89030,103390

515700947778409,2,1,1,1,1,1,1,1,0,21059,35604,50853,60098,73919,88675,103506

515700957879196,2,1,1,1,1,1,1,1,0,21326,35939,51492,60083,74249,89474,103761

[...]

Notice the tighter range of offsets? I began executing cpuunclaimed when the

system was idle, and it initialized the CPU timers more quickly, and then I

began the Linux kernel build.

Here's some different output, this time from a physical system with 4 CPUs,

also doing a kernel build,

# ./cpuunclaimed.py -J

TIMESTAMP_ns,CPU0,CPU1,CPU2,CPU3,OFFSET_ns_CPU0,OFFSET_ns_CPU1,OFFSET_ns_CPU2,OFFSET_ns_CPU3

4429382557480,1,1,1,1,0,6011,10895,16018

4429392655042,2,1,1,1,0,8217,13661,19378

4429402757604,1,1,1,1,0,6879,12433,18000

4429412857809,1,1,1,1,0,8303,13190,18719

4429422960709,2,1,1,1,0,6095,11234,17079

4429433060391,1,1,1,2,0,6747,12480,18070

4429443161699,1,1,1,1,0,6560,12264,17945

4429453262002,1,2,1,1,0,6992,12644,18341

4429463363706,1,2,1,1,0,6211,12071,17853

4429473465571,1,1,1,1,0,5766,11495,17638

4429483566920,1,1,1,1,0,5223,11736,16358

4429493666279,1,1,1,1,0,6964,12653,18410

4429503769113,1,1,1,1,0,5161,11399,16612

4429513870744,1,1,1,1,0,5943,10583,15768

4429523969826,1,1,1,1,0,6533,12336,18189

4429534070311,1,1,1,1,0,6834,12816,18488

4429544170456,1,1,1,1,0,7284,13401,19129

4429554274467,1,2,1,1,0,5941,11160,16594

4429564372365,1,2,1,1,0,7514,13618,19190

4429574474406,1,2,1,1,0,6687,12650,18248

4429584574220,1,2,1,1,0,7912,13705,19136

[...]

If the offset range becomes too great, we can no longer conclude about when

some CPUs were idle and others had queued work. The tool will detect this,

and print an error message and exit.

Some systems can power down CPUs when idle, and when they wake up again the

timed samples may resume from different offsets. If this happens, this tool

can no longer draw conclusions about when some CPUs were idle and others

had queued work, so it prints an error, and exits. Eg:

# ./cpuunclaimed.py 1

Sampling run queues... Output every 1 seconds. Hit Ctrl-C to end.

%CPU 0.25%, unclaimed idle 0.00%

%CPU 0.75%, unclaimed idle 0.00%

%CPU 0.25%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.12%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.25%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.12%, unclaimed idle 0.00%

%CPU 0.13%, unclaimed idle 0.00%

%CPU 0.12%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

%CPU 0.00%, unclaimed idle 0.00%

ERROR: CPU samples arrived at skewed offsets (CPUs may have powered down when idle), spanning 4328176 ns (expected < 4040404 ns). Debug with -J, and see the man page. As output may begin to be unreliable, exiting.

It's expected that this will only really occur on idle systems.

USAGE:

# ./cpuunclaimed.py -h

usage: cpuunclaimed.py [-h] [-j] [-J] [-T] [interval] [count]

Sample CPU run queues and calculate unclaimed idle CPU

positional arguments:

interval output interval, in seconds

count number of outputs

optional arguments:

-h, --help show this help message and exit

-j, --csv print sample summaries (verbose) as comma-separated values

-J, --fullcsv print sample summaries with extra fields: CPU sample

offsets

-T, --timestamp include timestamp on output

examples:

./cpuunclaimed # sample and calculate unclaimed idle CPUs,

# output every 1 second (default)

./cpuunclaimed 5 10 # print 5 second summaries, 10 times

./cpuunclaimed -T 1 # 1s summaries and timestamps

./cpuunclaimed -j # raw dump of all samples (verbose), CSV