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

Server NGINX
1

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:

#!/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 {} \;

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:

2

On Mon, Oct 18, 2010 at 03:54:12AM -0400, hakutoitoi wrote:

–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

41673 nginx 1 96 0 27480K 8040K select
0 11:27 0.05% nginx

Why do you use the poor select method ? FreeBSD has very good kqueue
method.
This CPU burst may be caused by nginx bug in select method handling.

–
Igor S.
http://sysoev.ru/en/

3

Igor,
Thank you for your advice.

I wanted to use kqueue and have configured using kqueue settings.
/usr/local/conf/nginx/nginx.conf

events {
    worker_connections  1024;
    use kqueue;
    multi_accept off;
}

error log outputs using kqueue event method.
/usr/local/logs/nginx/error

2010/10/18 20:48:32 [notice] 77055#0: using the "kqueue" event method
2010/10/18 20:48:32 [notice] 77055#0: nginx/0.7.67

but, I also use Embedded Perl module.

 ./configure --with-http_perl_module

configure with --with-http_perl_module

$ top
69650 nginx       1   4    0  2044K  1540K kqread 0   0:00  0.00% nginx

configure without --with-http_perl_module

$ top
77061 nginx       1  96    0  3828K  2124K select 0   0:00  0.00% nginx

as long as I use the Embedded Perl module, I can’t fix this problem?

Posted at Nginx Forum:

4

On Mon, Oct 18, 2010 at 11:29:46AM -0400, hakutoitoi wrote:

}

[code]
configure without --with-http_perl_module

$ top
> 77061 nginx       1  96    0  3828K  2124K select 0   0:00  0.00% nginx

as long as I use the Embedded Perl module, I can’t fix this problem?

Probably, you mixed up:

configure with --with-http_perl_module
kqueue
configure without --with-http_perl_module
select

It seems that you use perl code that works with remote servers or
databases
and this select is called by some perl module.

–
Igor S.
http://sysoev.ru/en/

5

sorry I mixed up.

configure with --with-http_perl_module
kqueue
configure without --with-http_perl_module
select

I tried simple config file(no use perl syntax)

$ cat /usr/local/conf/nginx/nginx.conf

user nginx users;
error_log logs/nginx/error  notice;
worker_rlimit_nofile 8192;
worker_processes 32;

pid /usr/local/var/run/nginx.pid;

events {
    worker_connections  1024;
    use kqueue;
    multi_accept off;
}

#include conf.d/*.conf;

configure with --with-http_perl_module

$ top
  PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU
COMMAND
 1551 root        1   4    0  3760K   664K select 1   3:31  0.00%
syslogd
 1605 root        1   8    0  3700K   432K nanslp 1   1:45  0.00% cron
 1600 root        1   4    0 14020K   952K select 1   0:38  0.00% sshd
52642 root        1   4    0 24928K  2996K sbwait 0   0:00  0.00% sshd
 5953 root        1   4    0  3592K  1916K select 1   0:00  0.00% nginx
 5959 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5979 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5966 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5963 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5972 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5975 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5977 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5954 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5958 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5988 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5976 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5986 nginx       1  96    0  3828K  2140K select 0   0:00  0.00% nginx
 5974 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5981 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5955 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5965 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5957 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5962 nginx       1  96    0  3828K  2132K select 1   0:00  0.00% nginx
 5985 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5961 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5973 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5964 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5968 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5967 nginx       1  96    0  3828K  2132K select 0   0:00  0.00% nginx
 5978 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5983 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5987 nginx       1  96    0  3828K  2140K select 0   0:00  0.00% nginx
 5982 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5970 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5980 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5984 nginx       1  96    0  3828K  2136K select 0   0:00  0.00% nginx
 5971 nginx       1   4    0  3828K  2136K select 1   0:00  0.00% nginx

configure without --with-http_perl_module

$ top
  PID USERNAME  THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU
COMMAND
 1551 root        1  96    0  3760K   664K select 0   3:31  0.00%
syslogd
 1605 root        1   8    0  3700K   432K nanslp 0   1:45  0.00% cron
 1600 root        1   4    0 14020K   952K select 1   0:38  0.00% sshd
99672 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
52642 root        1   4    0 24928K  2996K sbwait 0   0:00  0.00% sshd
99701 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99695 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99678 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99694 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99707 nginx       1   4    0  2020K  1508K kqread 0   0:00  0.00% nginx
99674 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99692 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99680 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99700 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99687 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99677 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99675 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99688 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99690 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99676 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99702 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99697 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99681 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99673 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99685 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99682 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99699 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99704 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99689 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99691 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99683 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99706 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99693 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99679 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99698 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx
99671 root        1  20    0  1796K  1296K pause  0   0:00  0.00% nginx
99703 nginx       1   4    0  2020K  1512K kqread 0   0:00  0.00% nginx

If I built nginx with --with-http_perl_module, it seems that nginx uses
select method instead of kqueue.

Posted at Nginx Forum: