|
Description
|
One of the CPU Caps tests failed because the CPU-intensive process was not getting any CPU
cycles at all. The test runs in a zone - the zone is rebooted during each test, zone cap is set and a process is started which does for(;;). The test verifies that the process
consumes the amount of CPU time consistent with the cap value.
System investigation shows that the zone exceeds its cap because of the activity in the
system project:
kstat -n /cpucaps/
module: caps instance: 106
name: cpucaps_project_0 class: project_caps
above_sec 0
below_sec 85
crtime 2002716.1197694
maxusage 146
nwait 0
snaptime 2002803.89193593
usage 98
value 18446743151372347932
zonename test_zone
module: caps instance: 106
name: cpucaps_project_1 class: project_caps
above_sec 0
below_sec 80
crtime 2002716.11978718
maxusage 2
nwait 0
snaptime 2002803.89362975
usage 0
value 18446743151372347932
zonename test_zone
module: caps instance: 106
name: cpucaps_zone_106 class: zone_caps
above_sec 85
below_sec 2
crtime 2002716.11974389
maxusage 146
nwait 10
snaptime 2002803.89507397
usage 98
value 50
zonename test_zone
Running prstat shows that there are two or three Java threads running:
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/LWPID
5575 noaccess 68M 42M sleep 59 0 0:00:57 1.5% java/12
5575 noaccess 68M 42M sleep 59 0 0:00:58 1.5% java/8
PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
5055 noaccess 15 34 0.0 0.0 0.0 0.0 51 0.1 .1M 0 .1M 0 java/5
5055 noaccess 15 34 0.0 0.0 0.0 0.0 51 0.1 .1M 0 .1M 0 java/10
Each one of them is using 50% of a CPU, so together they use 100% of a CPU which is
consistent with kstats.
Are they ever placed on wait queues?
dtrace -n sched:::cpucaps-sleep
dtrace: description 'sched:::cpucaps-sleep' matched 1 probe
Nope! - nothing shows up.
So these threads manage to run on a CPU, drive CPU utulization and avoid CPU caps
enforcement. No one else is able to run because the cap limit is exceeded and everyone
is placed on the wait queue.
These java threads belong to
5575 /usr/java/bin/java -server -Xmx128m -XX:+BackgroundCompilation -XX:PermSize=32m
so they are part of the web console management service. Indeed, disabling
svc:/system/webconsole:console
fixes the problem.
Why are these threads never placed on wait queues? The CPU caps enforcement is done during the tick processing in clock() in CL_TICK() function. Let's see whether something
interesting is going on there:
$ dtrace -n fbt::ts_tick:entry'{@[execname]=count()}'
dtrace: description 'fbt::ts_tick:entry' matched 1 probe
^C
sched 1
Nothing!!
So these threads consume tons of CPU time but are never seen on CPU during tick
processing - they always run between ticks and leave CPU before they can be cought!
What are these threads doing when they go on CPUs?
dtrace -n 'sched:::on-cpu,sched:::off-cpu/execname=="java"/{@[stack(20), ustack(20)]=count();}'
dtrace: description 'sched:::on-cpu,sched:::off-cpu' matched 3 probes
unix`resume+0x4
genunix`cv_timedwait_sig+0x148
genunix`cv_waituntil_sig+0x84
genunix`poll_common+0x13c
genunix`pollsys+0xcc
unix`syscall_trap32+0xcc
libc.so.1`__pollsys+0x4
libc.so.1`poll+0x7c
libjvm.so`__1cIos_sleep6Fxb_i_+0x9e4
libjvm.so`__1cCosFsleep6FpnGThread_xb_i_+0x240
libjvm.so`__1cNWatcherThreadDrun6M_v_+0x108
libjvm.so`java_start+0x138
libc.so.1`_lwp_start
200
unix`_resume_from_idle+0x1a4
genunix`cv_timedwait_sig+0x148
genunix`cv_waituntil_sig+0x84
genunix`poll_common+0x13c
genunix`pollsys+0xcc
unix`syscall_trap32+0xcc
libc.so.1`__pollsys+0x4
libc.so.1`poll+0x7c
libjvm.so`__1cIos_sleep6Fxb_i_+0x9e4
libjvm.so`__1cCosFsleep6FpnGThread_xb_i_+0x240
libjvm.so`__1cNWatcherThreadDrun6M_v_+0x108
libjvm.so`java_start+0x138
libc.so.1`_lwp_start
200
unix`resume+0x4
genunix`cv_timedwait_sig+0x148
genunix`cv_waituntil_sig+0x84
genunix`poll_common+0x13c
genunix`pollsys+0xcc
unix`syscall_trap32+0xcc
libc.so.1`__pollsys+0x4
libc.so.1`poll+0x7c
libjvm.so`__1cIos_sleep6Fxb_i_+0x9e4
libjvm.so`__1cCosFsleep6FpnGThread_xb_i_+0x240
libjvm.so`__1cWParallelTaskTerminatorRoffer_termination6M_b_+0xdc
libjvm.so`__1cJStealTaskFdo_it6MpnNGCTaskManager_I_v_+0x2ec
libjvm.so`__1cMGCTaskThreadDrun6M_v_+0x1f4
libjvm.so`java_start+0x138
libc.so.1`_lwp_start
1238
unix`_resume_from_idle+0x1a4
genunix`cv_timedwait_sig+0x148
genunix`cv_waituntil_sig+0x84
genunix`poll_common+0x13c
genunix`pollsys+0xcc
unix`syscall_trap32+0xcc
libc.so.1`__pollsys+0x4
libc.so.1`poll+0x7c
libjvm.so`__1cIos_sleep6Fxb_i_+0x9e4
libjvm.so`__1cCosFsleep6FpnGThread_xb_i_+0x240
libjvm.so`__1cWParallelTaskTerminatorRoffer_termination6M_b_+0xdc
libjvm.so`__1cJStealTaskFdo_it6MpnNGCTaskManager_I_v_+0x2ec
libjvm.so`__1cMGCTaskThreadDrun6M_v_+0x1f4
libjvm.so`java_start+0x138
libc.so.1`_lwp_start
1238
So they are constantly calling poll() for short sleeps. The call to poll() causes them to go asleep. They wake up eventually and clock thread places them on CPU when they go back
to user-land and quickly call poll() again. The are placed on a CPU by the clock()
thread, but it calls CL_TICK() before threads are placed on the run queue.
So here is the summary:
The svc:/system/webconsole:consol service starts java application which creates several
priority 59 threads consuming tons of CPU cycles by looping in sleep(). These threads
generate enough load to exceed the cap, but they are never seen by tick processing and
are never placed on the wait queue. As a result, CPU caps for them is not enforced and
everyone else is suffering.
Why these threads run at pri 59 and while they loop in sleep() is a potential subject of another bug.
Here is a little program that immediately demonstrates the issue. Running it while
cap is set to less than 50% prevents anything else from running in the same
project/zone and this program is never capped.
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <poll.h>
#include <sys/time.h>
#define NSEC_IN_MSEC (NANOSEC / MILLISEC)
#define DELTA (9 * NSEC_IN_MSEC)
int f(int x)
{
return (x+1);
}
int main(int argc, char *argv[])
{
for (;;) {
int i;
int y = 0;
hrtime_t t1, t2;
int rc = poll(NULL, 0, 1);
t1 = gethrtime();
t2 = t1 + DELTA;
while (gethrtime() < t2) {
y += f(i);
/* yield(); */
}
}
}
|
