nginx causes cpu burst problem when it is received USR1 signal by logrotate script

Mon Oct 18 11:54:12 MSD 2010

Hi,

I'm using nginx/0.7.67 on the freebsd-6.4
$ nginx -V
nginx version: nginx/0.7.67
built by gcc 2.95.3 20010315 (release)
configure arguments: --prefix=/usr/local
--conf-path=/usr/local/conf/nginx/nginx.conf
--pid-path=/usr/local/var/run/nginx.pid
--lock-path=/usr/local/var/run/nginx.lock
--http-client-body-temp-path=/usr/local/var/run/nginx/client_body_temp
--http-proxy-temp-path=/usr/local/var/run/nginx/proxy_temp
--error-log-path=/usr/local/logs/nginx/error
--http-log-path=/usr/local/logs/nginx/access --with-select_module
--with-http_perl_module --with-debug --with-http_stub_status_module

I'm using the following script as root user for logrotation:
[code]
#!/bin/sh

mv /usr/local/logs/nginx/error /usr/local/logs/nginx/error.`date
"+%Y%m%d"`
mv /usr/local/logs/nginx/access /usr/local/logs/nginx/access.`date
"+%Y%m%d"`

kill -USR1 `cat /usr/local/var/run/nginx.pid`

find /usr/local/logs/nginx/ -ctime +30 -exec rm {} \;
[/code]

Log rotation succeed. but, 
Occasionally the above script causes master process' cpu burst until
next logrotate time.

top command outputs following:
[code]
$ top
last pid: 91548;  load averages:  1.00,  1.02,  1.01
101 processes: 5 running, 78 sleeping, 18 waiting
CPU:  7.8% user,  0.0% nice, 43.4% system,  0.0% interrupt, 48.8%
idle
Mem: 91M Active, 1617M Inact, 181M Wired, 68M Cache, 213M Buf, 19M Free
Swap: 4096M Total, 4K Used, 4096M Free

  PID USERNAME       THR PRI NICE   SIZE    RES STATE 
C   TIME   WCPU COMMAND
41661 root             1 113    0 27172K  7716K CPU1  
1 486:03 99.02% nginx
   11 root             1 171   52     0K    16K
RUN    0    ??? 94.97% idle: cpu0
   10 root             1 171   52     0K    16K
RUN    1    ???  1.56% idle: cpu1
41673 nginx            1  96    0 27480K  8040K select
0  11:27  0.05% nginx
   12 root             1 -44 -163     0K    16K
WAIT   0  20.6H  0.00% swi1: net
   22 root             1 -68    0     0K    16K
-      0 872:49  0.00% em0 taskq
   24 root             1 -68 -187     0K    16K
WAIT   0 638:23  0.00% irq16: em0 uhci0+
   13 root             1 -32 -151     0K    16K
WAIT   0 476:52  0.00% swi4: clock sio
   43 root             1  20    0     0K    16K
syncer 0 144:55  0.00% syncer
   41 root             1 171   52     0K    16K
pgzero 0 130:24  0.00% pagezero
   46 root             1 -32    0     0K    16K
-      0  39:09  0.00% schedcpu
    3 root             1  -8    0     0K   
16K -      0  35:15  0.00% g_up
    4 root             1  -8    0     0K   
16K -      0  31:01  0.00% g_down
    2 root             1  -8    0     0K   
16K -      0  25:47  0.00% g_event
 6635 root             1  96    0 14024K  2308K select
0  25:16  0.00% sshd
  640 root             1  96    0  7576K  1692K
select 0  20:49  0.00% ntpd
41672 nginx            1  96    0 27484K  8048K select
0  11:56  0.00% nginx
41692 nginx            1  96    0 27484K  8044K select
0  11:55  0.00% nginx
41666 nginx            1  96    0 27480K  8044K select
0  11:51  0.00% nginx
41682 nginx            1  96    0 27480K  8040K select
0  11:50  0.00% nginx
41691 nginx            1  96    0 27488K  8048K select
0  11:50  0.00% nginx
41663 nginx            1  96    0 27476K  8040K select
0  11:50  0.00% nginx
41664 nginx            1  96    0 27476K  8040K select
0  11:48  0.00% nginx
41676 nginx            1  96    0 27480K  8040K
RUN    0  11:46  0.00% nginx
41686 nginx            1  96    0 27484K  8044K select
0  11:45  0.00% nginx
41671 nginx            1  96    0 27476K  8040K select
0  11:43  0.00% nginx
41687 nginx            1  96    0 27480K  8040K select
0  11:43  0.00% nginx
41662 nginx            1  96    0 27476K  8040K select
0  11:40  0.00% nginx
41685 nginx            1  96    0 27480K  8040K select
0  11:40  0.00% nginx
41675 nginx            1  96    0 27480K  8040K select
0  11:37  0.00% nginx
41681 nginx            1  96    0 27480K  8040K select
0  11:37  0.00% nginx
41680 nginx            1  96    0 27476K  8036K select
0  11:37  0.00% nginx
41674 nginx            1  96    0 27476K  8036K select
0  11:36  0.00% nginx
41690 nginx            1  96    0 27484K  8044K select
0  11:34  0.00% nginx
41688 nginx            1  96    0 27480K  8040K select
0  11:33  0.00% nginx
41670 nginx            1  96    0 27484K  8048K select
0  11:33  0.00% nginx
41689 nginx            1  96    0 27484K  8044K select
0  11:33  0.00% nginx
[code]

normally top command outputs following:
[code]
$ top
last pid: 43789;  load averages:  0.00,  0.00,  0.00
108 processes: 3 running, 87 sleeping, 18 waiting
CPU:  0.0% user,  0.0% nice,  0.4% system,  0.0% interrupt, 99.6%
idle
Mem: 102M Active, 1604M Inact, 181M Wired, 73M Cache, 213M Buf, 16M
Free
Swap: 4096M Total, 4K Used, 4096M Free

  PID USERNAME       THR PRI NICE   SIZE    RES STATE 
C   TIME   WCPU COMMAND
   10 root             1 171   52     0K    16K
CPU1   1    ??? 99.02% idle: cpu1
   11 root             1 171   52     0K    16K
RUN    0    ??? 97.61% idle: cpu0
60947 root             1  96    0 27172K  7712K select
0  24.0H  0.00% nginx
   12 root             1 -44 -163     0K    16K
WAIT   0  20.8H  0.00% swi1: net
   22 root             1 -68    0     0K    16K
-      0 884:49  0.00% em0 taskq
   24 root             1 -68 -187     0K    16K
WAIT   0 644:02  0.00% irq16: em0 uhci0+
   13 root             1 -32 -151     0K    16K
WAIT   0 481:46  0.00% swi4: clock sio
   43 root             1  20    0     0K    16K
syncer 0 144:23  0.00% syncer
   41 root             1 171   52     0K    16K
pgzero 1 128:31  0.00% pagezero
   46 root             1 -16    0     0K    16K
-      0  40:48  0.00% schedcpu
    3 root             1  -8    0     0K   
16K -      0  35:22  0.00% g_up
    4 root             1  -8    0     0K   
16K -      0  31:20  0.00% g_down
    2 root             1  -8    0     0K   
16K -      0  26:14  0.00% g_event
 6652 root             1  96    0 14024K  2332K select
0  24:07  0.00% sshd
  640 root             1  96    0  7576K  1692K
select 0  20:52  0.00% ntpd
60951 nginx            1  96    0 27476K  8032K select
0  13:17  0.00% nginx
60968 nginx            1  96    0 27484K  8040K select
0  13:14  0.00% nginx
60972 nginx            1  96    0 27488K  8044K select
0  13:12  0.00% nginx
60956 nginx            1  96    0 27580K  8140K select
0  13:10  0.00% nginx
60954 nginx            1  96    0 27480K  8040K select
0  13:09  0.00% nginx
60974 nginx            1  96    0 27484K  8040K select
0  13:05  0.00% nginx
60969 nginx            1  96    0 27480K  8036K select
0  12:59  0.00% nginx
60978 nginx            1  96    0 27484K  8040K select
0  12:59  0.00% nginx
60967 nginx            1  96    0 27480K  8036K select
0  12:59  0.00% nginx
60977 nginx            1  96    0 27484K  8040K select
0  12:59  0.00% nginx
60949 nginx            1  96    0 27480K  8036K select
0  12:57  0.00% nginx
60948 nginx            1  96    0 27476K  8032K select
0  12:57  0.00% nginx
60975 nginx            1  96    0 27480K  8036K select
0  12:57  0.00% nginx
60953 nginx            1  96    0 27476K  8036K select
0  12:55  0.00% nginx
60965 nginx            1  96    0 27484K  8040K select
0  12:54  0.00% nginx
60961 nginx            1  96    0 27480K  8036K select
0  12:54  0.00% nginx
60958 nginx            1  96    0 27476K  8036K select
0  12:53  0.00% nginx
60970 nginx            1  96    0 27480K  8036K select
0  12:52  0.00% nginx
60964 nginx            1  96    0 27480K  8036K select
0  12:52  0.00% nginx
60966 nginx            1  96    0 27480K  8036K select
0  12:52  0.00% nginx
60976 nginx            1  96    0 27484K  8040K select
0  12:52  0.00% nginx
60971 nginx            1  96    0 27480K  8036K select
0  12:50  0.00% nginx
[code]

Am I doing something wrong?

Regards,

Posted at Nginx Forum: http://forum.nginx.org/read.php?2,141795,141795#msg-141795