freebsd stable - Feb 2015 - High load w/ almost no CPU usage

Hello all,

I've been writing some software to replace some off the shelf call 
center software. It is designed to interface with freeswitch as the 
underlying telephony platform. The 10.1-RELEASE-p4 host that runs 
freeswitch consumes 0% to < 10% CPU and has a load that for the most 
part fluctuates between 0 and 2. But at seemingly random intervals, the 
load average jumps to a very high value, and then eventually drops back 
down to < 2.  I should add that it doesn't matter how many calls are 
going through the system, as this issue occurs after hours when there 
are no calls at all.

I tried to do a bunch of googling to see if this was a common problem. I 
did run across some suggestions to change the following sysctls which 
did nothing to fix the issue ...

kern.eventtimer.timer: LAPIC
kern.timecounter.hardware: ACPI-fast

Does anyone have a suggestion on what I can do to trouble shoot this 
issue? I'd rather not dump FreeBSD in favor of Linux ( which appears to 
be the preferred freeswitch dev platform ), I'm just not sure where to 
go from here.

TOP OUTPUT
-----------------

last pid:  6169;  load averages: 47.40, 27.43, 18.03 
                                       up 18+01:07:12  20:07:26
34 processes:  1 running, 33 sleeping
CPU:  0.7% user,  0.0% nice,  1.2% system,  0.0% interrupt, 98.1% idle
Mem: 177M Active, 6300M Inact, 1184M Wired, 824M Buf, 252M Free
Swap: 2048M Total, 2048M Free

   PID USERNAME    THR PRI NICE   SIZE    RES STATE   C   TIME WCPU COMMAND
45288 root        281 -22 r30F   735M   547M select  2 194:15 0.00% 
freeswitch
   684 root          1  20    0 25448K  3916K select  1   0:42 0.00% ntpd
82924 rdj           3  20    0 89424K 17852K select  2   0:41 0.00% dialyd
   540 root          1  20    0 14492K  2140K select  1   0:30 0.00% 
syslogd
55847 zabbix        1  20    0 25552K  3164K nanslp  1   0:29 0.00% 
zabbix_agentd
55849 zabbix        1  20    0 25552K  3244K accept  2   0:17 0.00% 
zabbix_agentd
55850 zabbix        1  20    0 25552K  3236K accept  3   0:17 0.00% 
zabbix_agentd
55848 zabbix        1  20    0 25552K  3176K select  2   0:16 0.00% 
zabbix_agentd
   741 root          1  20    0 24108K  5488K select  3   0:14 0.00% 
sendmail
55851 zabbix        1  20    0 25552K  2928K nanslp  0   0:13 0.00% 
zabbix_agentd
   748 root          1  20    0 16592K  2260K nanslp  0   0:02 0.00% cron
73342 mgrooms       1  20    0 86476K  8012K select  3   0:01 0.00% sshd
73338 root          1  20    0 86476K  7932K select  0   0:00 0.00% sshd
   460 root          1  20    0 13164K  4508K select  3   0:00 0.00% devd
56103 root          1  20    0 61208K  7492K select  3   0:00 0.00% sshd
   744 smmsp         1  20    0 24108K  5100K pause   3   0:00 0.00% 
sendmail
  6163 mgrooms       1  20    0 21916K  2996K CPU0    0   0:00 0.00% top
  6158 root          1  21    0 86476K  7932K select  0   0:00 0.00% sshd
73343 mgrooms       1  20    0 17656K  3492K wait    0   0:00 0.00% bash
73402 root          1  22    0 17656K  3492K ttyin   1   0:00 0.00% bash
73401 mgrooms       1  20    0 47716K  2808K wait    0   0:00 0.00% su
  6161 mgrooms       1  20    0 86476K  7932K select  3   0:00 0.00% sshd
  6162 mgrooms       1  20    0 17656K  3480K wait    0   0:00 0.00% bash
   794 root          1  52    0 14488K  1980K ttyin   1   0:00 0.00% getty
   799 root          1  52    0 14488K  1980K ttyin   1   0:00 0.00% getty
   796 root          1  52    0 14488K  1980K ttyin   2   0:00 0.00% getty
   798 root          1  52    0 14488K  1980K ttyin   3   0:00 0.00% getty
   800 root          1  52    0 14488K  1980K ttyin   3   0:00 0.00% getty
   795 root          1  52    0 14488K  1980K ttyin   0   0:00 0.00% getty
   797 root          1  52    0 14488K  1980K ttyin   2   0:00 0.00% getty
   801 root          1  52    0 14488K  1980K ttyin   0   0:00 0.00% getty
55846 zabbix        1  29    0 25552K  2872K wait    3   0:00 0.00% 
zabbix_agentd
   141 root          1  52    0 12332K  1788K pause   0   0:00 0.00% 
adjkerntz
   443 root          1  52    0 16704K  2024K select  3   0:00 0.00% moused

Thanks in advance,

-Matthew

On Thu, Feb 5, 2015 at 12:45 PM, Matthew Grooms <mgrooms at shrew.net>
wrote:
> But at seemingly random intervals, the load average jumps to a very high
> value, and then eventually drops back down to < 2.

One problem with using top to diagnose this kind of thing is that you can
have processes that have very short activation periods, which won't show up
much in top because they don't run for long enough to collect much CPU time
or indeed to produce user-noticeable load, but will drive the apparent load
up because they're on the run queue so much. dtrace probes might be more
helpful here.

Also you might want to look at interrupts (e.g. monitor "vmstat -i"
output,
then again move to dtrace for finer grained monitoring).

-- 
brandon s allbery kf8nh                               sine nomine associates
allbery.b at gmail.com                                  ballbery at
sinenomine.net
unix, openafs, kerberos, infrastructure, xmonad        http://sinenomine.net

Matthew Grooms wrote this message on Thu, Feb 05, 2015 at 11:45
-0600:
> 45288 root        281 -22 r30F   735M   547M select  2 194:15 0.00% 
281 is a lot of threads...  Try running w/ top -H to split out the
threads into seperate lines...  Also, look at how quickly the cpu time
grows on this process...  As it looks like most of the cpu is on this
thread, you should be able to do (cpu use over time) / ncores and get
a better picture of how much cpu this process is using...

Also, you might want to look at using dtrace to profile the process
to see what is happening..  It could be that freeswitch rolled it's
own spin locks, and when some maintainance task triggers, it wakes
everyone up, but can't make much progress since some are spinning
waiting for another lock..

Good luck!

-- 
  John-Mark Gurney				Voice: +1 415 225 5579

     "All that I will do, has been done, All that I have, has not."