[Dovecot] FreeBSD 6.1-RELEASE/kqueue high CPU load

Taras Savchuk taras at elantech.ru
Tue Sep 19 02:21:06 EEST 2006


LI Xin пишет:
> Taras Savchuk wrote:
>   
>> LI Xin пишет:
>>     
>>> Paul Lathrop wrote:
>>>  
>>>       
>>>> Taras Savchuk wrote:
>>>>    
>>>>         
>>>>> Hi to ALL!
>>>>>
>>>>> I have dovecot-1.0r7 installed on FreeBSD 6.1, using kqueue and
>>>>> Maildir (<20 mailboxes, < 0,5 Gb size). Periodically CPU load of imap
>>>>> processes increasing up to 60-80%.
>>>>> Is it normall behavior or not? May be somebody had such kind of
>>>>> problems?
>>>>>
>>>>>       
>>>>>           
>>>> I have also experienced this behavior, which is quite bothersome because
>>>> I sold my supervisor on Dovecot by talking about performance and low
>>>> resource requirements...
>>>>     
>>>>         
>>> What if you get some output from ktrace/kdump?  Additionally, try to
>>> force the process to save a coredump and investigate its .core with gdb
>>> would help tracking down the issue...
>>>
>>> Note that because when using kqueue the process should get a "kqread" if
>>> it is waiting for kqueue event.  If the process is stuck in "RUN" state
>>> then a coredump would be more helpful.
>>>
>>> Cheers,
>>>   
>>>       
>> I cought imap while eating much CPU (~80%) and run ktrace -t + -p <bad
>> process pid>.
>> It's kdump -E output, many gettimeofday() calls, is it normal? :
>>
>> mail2# kdump -E -f ktrace.out | less
>> 26208 imap     0.000000 RET   kevent 0
>> 26208 imap     0.000042 CALL  gettimeofday(0x80c2c60,0x80c2c68)
>> 26208 imap     0.000046 RET   gettimeofday 0
>> 26208 imap     0.000061 CALL  gettimeofday(0xbfbfe9a0,0)
>> 26208 imap     0.000064 RET   gettimeofday 0
>> 26208 imap     0.000078 CALL  kevent(0x4,0,0,0x80d1000,0x5,0xbfbfe998)
>> 26208 imap     0.000082 RET   kevent 0
>> 26208 imap     0.000100 CALL  gettimeofday(0x80c2c60,0x80c2c68)
>> 26208 imap     0.000103 RET   gettimeofday 0
>> 26208 imap     0.000116 CALL  gettimeofday(0xbfbfe9a0,0)
>> 26208 imap     0.000119 RET   gettimeofday 0
>> 26208 imap     0.000131 CALL  kevent(0x4,0,0,0x80d1000,0x5,0xbfbfe998)
>> 26208 imap     0.474998 RET   kevent 0
>>     
> [snip]
>
> This looks quite normal...  I am not really sure about what is
> happening.  Is the CPU consumed by in-kernel operation?  (systat -vm  or
> top's output would be helpful)
>
> Cheers,
>   
Here are top's ans systat -vm 's output:

mail2# top
last pid: 68406;  load averages:  1.09,  0.55,  
0.38                                                  up 1+09:40:06  
03:18:34
139 processes: 2 running, 137 sleeping
CPU states:  7.1% user,  0.0% nice, 43.0% system,  0.0% interrupt, 49.9% 
idle
Mem: 942M Active, 777M Inact, 175M Wired, 85M Cache, 112M Buf, 24M Free
Swap: 2022M Total, 2022M Free

  PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU COMMAND
61291 email       1 114    0  3528K  2120K RUN    0   3:09 85.50% imap
62547 email       1   4    0  6168K  2644K kqread 0   0:32  3.81% imap
60522 email       1   4    0  3416K  1860K kqread 0   0:23  0.24% imap
 2083  10005      1   4    0   198M 95412K accept 0  27:40  0.00% httpd
 2085  10005      1   4    0   198M 93952K accept 0  16:09  0.00% httpd
 2084  10005      1   4    0   198M 94912K accept 0  16:01  0.00% httpd
 2231 mysql       1   4   14   524M   409M sbwait 0   9:37  0.00% mysqld
 1569  10003      1   4    0   153M 31936K accept 0   7:47  0.00% httpd
 1570  10003      1   4    0   159M 38560K accept 0   7:46  0.00% httpd
 1573 mysql       1   4   14   524M   409M sbwait 0   6:09  0.00% mysqld
 2232 mysql       1   4   14   524M   409M sbwait 0   6:08  0.00% mysqld
 2229 mysql       1   4   14   524M   409M sbwait 0   3:13  0.00% mysqld
 1565 mysql       1   4   14   524M   409M sbwait 0   3:11  0.00% mysqld
 1213  10001      1   4    0   171M 61252K accept 0   1:54  0.00% httpd
 1212  10001      1   4    0   153M 43660K accept 0   1:51  0.00% httpd
 1211  10001      1   4    0   153M 42052K accept 0   1:51  0.00% httpd
 1010 elantech    1  20    0   155M 77364K lockf  0   1:38  0.00% httpd
 1009 elantech    1   4    0   168M 93660K kqread 0   1:37  0.00% httpd
 1011 elantech    1  20    0   161M 86424K lockf  0   1:33  0.00% httpd
 2234 mysql       1   4   14   524M   409M sbwait 0   1:01  0.00% mysqld
 2184 mysql       1   4   14   524M   409M sbwait 0   0:57  0.00% mysqld
 2227 mysql       1   4   14   524M   409M sbwait 0   0:56  0.00% mysqld
 1366  10002      1  20    0   161M 48900K lockf  0   0:39  0.00% httpd
 1367  10002      1   4    0   153M 41364K kqread 0   0:38  0.00% httpd
  662 mysql       1  20   14   524M   409M pause  0   0:13  0.00% mysqld
  658 mysql       1 110   14   524M   409M select 0   0:09  0.00% mysqld
 2230 mysql       1   4   14   524M   409M sbwait 0   0:09  0.00% mysqld
 2233 mysql       1   4   14   524M   409M sbwait 0   0:08  0.00% mysqld
  657 mysql       1 110   14   524M   409M select 0   0:08  0.00% mysqld
  611 mysql       1  20   14   524M   409M pause  0   0:06  0.00% mysqld
  405 bind        1   4    0  5672K  4420K select 0   0:04  0.00% named
  613 root        1   4    0  1396K   964K kqread 0   0:03  0.00% dovecot
65753 root        1  96    0  2632K  1680K CPU0   0   0:03  0.00% top
  632 root        1   4    0  2412K  1624K kqread 0   0:02  0.00% 
dovecot-auth
  610 mysql       1  20   14   524M   409M pause  0   0:02  0.00% mysqld
mail2# systat -vm
    2 users    Load  1.08  0.56  0.39                  19 сен 03:18

Mem:KB    REAL            VIRTUAL                     VN PAGER  SWAP PAGER
        Tot   Share      Tot    Share    Free         in  out     in  out
Act  967396   18100  1858368    36796  111372 count
All 2021620   26420 83531252    51592         pages
                                                                 Interrupts
Proc:r  p  d  s  w    Csw  Trp  Sys  Int  Sof  Flt        cow    4078 total
     2      136       266  177 4433   89       133 179244 wire        
16: bge
                                                   964268 act         
20: ata
50.0%Sys   0.0%Intr  0.0%User  0.0%Nice 50.0%Idl   795616 inact  2039 
cpu0: time
|    |    |    |    |    |    |    |    |    |      86660 cache  2039 
cpu1: time
=========================                           24712 free
                                                          daefr
Namei         Name-cache    Dir-cache                     prcfr
    Calls     hits    %     hits    %                     react
        4        4  100                                   pdwake
                                      133 zfod            pdpgs
Disks   ad4                               ozfod           intrn
KB/t   0.00                               %slo-z   114464 buf
tps       0                               tfree        97 dirtybuf
MB/s   0.00                                        100000 desiredvnodes
% busy    0                                         87066 numvnodes
                                                    24995 freevnodes

-- 
С уважением, Савчук Тарас
ООО "Элантек" : Аутсорсинг ИТ, WEB-разработка
+7 (495) 589 68 81
+7 (926) 575 22 11
http://www.elantech.ru
info at elantech.ru



More information about the dovecot mailing list