hi all, [nginx]"accept_mutex on" cause 1s delay

classic Classic list List threaded Threaded
2 messages Options
lx
Reply | Threaded
Open this post in threaded view
|

hi all, [nginx]"accept_mutex on" cause 1s delay

lx
hi all: 
      I use nginx-1.16.0, nginx  is running on X86 embedded devices. The embedded device has 4 CPU, CPU type is: "Intel(R) Atom(TM) CPU D525   @ 1.80GHz".
When I use "accpet_mutex on", nginx use 1 secod for get static file.

events {
use epoll;
    accept_mutex on;
    worker_connections  10240;
}


The debug log is:
###########################################################################
2019/11/08 17:08:10 [debug] 2552#2552: *1 post access phase: 12                                                                                                                              
2019/11/08 17:08:10 [debug] 2552#2552: *1 generic phase: 13                                                                                                                                  
2019/11/08 17:08:10 [debug] 2552#2552: *1 generic phase: 14                                                                                                                                  
2019/11/08 17:08:10 [debug] 2552#2552: *1 http script copy: "http://"                                                                                                                        
2019/11/08 17:08:10 [debug] 2552#2552: *1 http script var: "pcdnapkwsdl2.com.cn"                                                                                                        
2019/11/08 17:08:10 [debug] 2552#2552: *1 http script copy: "/"                                                                                                                              
2019/11/08 17:08:10 [debug] 2552#2552: *1 http script var: "appstore/developer/soft/20191008/201910081449521157660_v2_820_811.patch"                                                         
2019/11/08 17:08:10 [debug] 2552#2552: *1 http init upstream, client timer: 0                                                                                                                
2019/11/08 17:08:10 [debug] 2552#2552: *1 epoll add event: fd:15 op:3 ev:80002005                                                                                                            
2019/11/08 17:08:10 [debug] 2552#2552: *1 http cache key: "http://pcdnapkwsdl2.vivo.com.cn"                                                                                                  
2019/11/08 17:08:10 [debug] 2552#2552: *1 http cache key: "/appstore/developer/soft/20191008/201910081449521157660_v2_820_811.patch"                                                         
2019/11/08 17:08:10 [debug] 2552#2552: *1 add cleanup: 00000000026C46C0                                                                                                                      
2019/11/08 17:08:10 [debug] 2552#2552: shmtx lock                                                                                                                                            
2019/11/08 17:08:10 [debug] 2552#2552: shmtx unlock                                                                                                                                          
2019/11/08 17:08:10 [debug] 2552#2552: *1 http file cache exists: 0 e:1                                                                                                                      
2019/11/08 17:08:10 [debug] 2552#2552: *1 cache file: "/tmp/storage/youyu/ikcdndata/wangsu2/wan1/p2p_proxy/cache/c/df/468f0ede6aa8ba9073f9a989b8377dfc"                                      
2019/11/08 17:08:10 [debug] 2552#2552: *1 add cleanup: 00000000026C4740                                                                                                                      
2019/11/08 17:08:10 [debug] 2552#2552: *1 http file cache fd: 16                                                                                                                             
2019/11/08 17:08:10 [debug] 2552#2552: *1 malloc: 00000000026C48D0:4096                                                                                                                      
2019/11/08 17:08:10 [debug] 2552#2552: *1 thread read: 16, 00000000026C48D0, 4096, 0                                                                                                         
2019/11/08 17:08:10 [debug] 2552#2552: task #0 added to thread pool "default"                                                                                                                
2019/11/08 17:08:10 [debug] 2552#2552: *1 http upstream cache: -2                                                                                                                            
2019/11/08 17:08:10 [debug] 2552#2552: *1 http request count:2 blk:1                                                                                                                         
2019/11/08 17:08:10 [debug] 2552#2552: worker cycle                                                                                                                                          
2019/11/08 17:08:10 [debug] 2552#2552: accept mutex locked                                                                                                                                   
2019/11/08 17:08:10 [debug] 2552#2552: epoll timer: -1                                                                                                                                       
2019/11/08 17:08:11 [debug] 2552#2552: epoll: fd:15 ev:0004 d:00007F026302A3F0                                                                         
2019/11/08 17:08:11 [debug] 2552#2552: *1 post event 00007F0262E48190                                                                                                                        
2019/11/08 17:08:11 [debug] 2552#2552: timer delta: 533                                                                                                                                      
2019/11/08 17:08:11 [debug] 2552#2552: posted event 00007F0262E48190                                                                                                                         
2019/11/08 17:08:11 [debug] 2552#2552: *1 delete posted event 00007F0262E48190                                                                                                               
2019/11/08 17:08:11 [debug] 2552#2552: worker cycle                                                                                                                                          
2019/11/08 17:08:11 [debug] 2552#2552: accept mutex locked                                                                                                                                   
2019/11/08 17:08:11 [debug] 2552#2552: epoll timer: -1                                                                                                                                       
2019/11/08 17:08:11 [debug] 2552#2564: run task #0 in thread pool "default"                                                                                                                  
2019/11/08 17:08:11 [debug] 2552#2564: thread read handler                                                                                                                                   
2019/11/08 17:08:11 [debug] 2554#2554: timer delta: 809                 
2019/11/08 17:08:11 [debug] 2554#2554: worker cycle
2019/11/08 17:08:11 [debug] 2554#2554: accept mutex lock failed: 02019/11/08 17:08:11 [debug] 2554#2554: epoll timer: 500                                       
2019/11/08 17:08:11 [debug] 2553#2553: timer delta: 809
2019/11/08 17:08:11 [debug] 2553#2553: worker cycle
2019/11/08 17:08:11 [debug] 2553#2553: accept mutex lock failed: 0
2019/11/08 17:08:11 [debug] 2553#2553: epoll timer: 500
2019/11/08 17:08:11 [debug] 2555#2555: timer delta: 811
2019/11/08 17:08:11 [debug] 2555#2555: worker cycle                                           
2019/11/08 17:08:11 [debug] 2555#2555: accept mutex lock failed: 0                            
2019/11/08 17:08:11 [debug] 2555#2555: epoll timer: 500                                       
2019/11/08 17:08:11 [debug] 2552#2564: pread: 4096 (err: 0) of 4096 @0                        
2019/11/08 17:08:11 [debug] 2552#2564: complete task #0 in thread pool "default"              
2019/11/08 17:08:11 [debug] 2552#2552: epoll: fd:11 ev:0001 d:000000000086FF20                
2019/11/08 17:08:11 [debug] 2552#2552: post event 000000000086FEC0
2019/11/08 17:08:11 [debug] 2552#2552: timer delta: 343
2019/11/08 17:08:11 [debug] 2552#2552: posted event 000000000086FEC0
2019/11/08 17:08:11 [debug] 2552#2552: delete posted event 000000000086FEC0                   
2019/11/08 17:08:11 [debug] 2552#2552: thread pool handler2019/11/08 17:08:11 [debug] 2552#2552: run completion handler for task #0                     
2019/11/08 17:08:11 [debug] 2552#2552: *1 thread read: 16, 00000000026C48D0, 4096, 0
2019/11/08 17:08:11 [debug] 2552#2552: *1 http upstream cache: 0
2019/11/08 17:08:11 [debug] 2552#2552: *1 posix_memalign: 00000000026C58E0:4096 @16
2019/11/08 17:08:11 [debug] 2552#2552: *1 http proxy status 200 "200 OK"
###########################################################################

If  I  don't use "accpet_mutex on" , I can get  http response quickly. The debug log is:
###########################################################################
2019/11/08 17:14:34 [debug] 23726#23726: *1 malloc: 000000000226E8D0:4096                                                                                                                    
2019/11/08 17:14:34 [debug] 23726#23726: *1 thread read: 17, 000000000226E8D0, 4096, 0                                                                                                       
2019/11/08 17:14:34 [debug] 23726#23726: task #0 added to thread pool "default"                                                                                                              
2019/11/08 17:14:34 [debug] 23726#23726: *1 http upstream cache: -2                                                                                                                          
2019/11/08 17:14:34 [debug] 23726#23795: run task #0 in thread pool "default"                                                                                                                
2019/11/08 17:14:34 [debug] 23726#23726: *1 http finalize request: -4, "/pcdnapkwsdl2.com.cn/pcdnapkwsdltest.com.cn/appstore/developer/soft/20191008/201910081449521157660_v2_820_8
2019/11/08 17:14:34 [debug] 23726#23795: thread read handler                                                                                                                                 
2019/11/08 17:14:34 [debug] 23726#23726: *1 http request count:2 blk:1                                                                                                                       
2019/11/08 17:14:34 [debug] 23726#23726: timer delta: 2                                                                                                                                      
2019/11/08 17:14:34 [debug] 23726#23795: pread: 4096 (err: 0) of 4096 @0                                                                                                                     
2019/11/08 17:14:34 [debug] 23726#23726: worker cycle                                                                                                                                        
2019/11/08 17:14:34 [debug] 23726#23795: complete task #0 in thread pool "default"                                                                                                           
2019/11/08 17:14:34 [debug] 23726#23726: epoll timer: -1                                                                                                                                     
2019/11/08 17:14:34 [debug] 23726#23726: epoll: fd:16 ev:0004 d:00007F3D265033F0                                                                                                             
2019/11/08 17:14:34 [debug] 23726#23726: timer delta: 0                                                                                                                                      
2019/11/08 17:14:34 [debug] 23726#23726: worker cycle                                                                                                                                        
2019/11/08 17:14:34 [debug] 23726#23726: epoll timer: -1                                                                                                                                     
2019/11/08 17:14:34 [debug] 23726#23726: epoll: fd:13 ev:0001 d:000000000086FF20                                                                                                             
2019/11/08 17:14:34 [debug] 23726#23726: thread pool handler                                                                                                                                 
2019/11/08 17:14:34 [debug] 23726#23726: run completion handler for task #0                                                                                                                  
2019/11/08 17:14:34 [debug] 23726#23726: *1 thread read: 17, 000000000226E8D0, 4096, 0                                                                                                       
2019/11/08 17:14:34 [debug] 23726#23726: shmtx lock                                                                                                                                          
2019/11/08 17:14:34 [debug] 23726#23726: shmtx unlock                                                                                                                                        
2019/11/08 17:14:34 [debug] 23726#23726: *1 http upstream cache: 0                                                                                                                           
2019/11/08 17:14:34 [debug] 23726#23726: *1 posix_memalign: 000000000226F8E0:4096 @16                                                                                                        
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy status 200 "200 OK"                                                                                                                   
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Date: Fri, 08 Nov 2019 07:50:58 GMT"                                                                                         
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Content-Type: application/octet-stream"                                                                                      
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Content-Length: 40492454"                                                                                                    
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Connection: close"                                                                                                           
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Server: AliyunOSS"                                                                                                           
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "x-oss-request-id: 5D9C3B95591574F5686E7B00"                                                                                  
2019/11/08 17:14:34 [debug] 23726#23726: *1 http proxy header: "Accept-Ranges: bytes"                            
###########################################################################

How should this problem be analyzed? I am a newcomer to nginx.
Thank you.




_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: hi all, [nginx]"accept_mutex on" cause 1s delay

Francis Daly
On Mon, Nov 11, 2019 at 11:26:30AM +0800, lx wrote:

Hi there,

>       I use nginx-1.16.0, nginx  is running on X86 embedded devices. The
> embedded device has 4 CPU, CPU type is: "Intel(R) Atom(TM) CPU D525   @
> 1.80GHz".
> When I use "accpet_mutex on", nginx use 1 secod for get static file.

> If  I  don't use "accpet_mutex on" , I can get  http response quickly.

> How should this problem be analyzed? I am a newcomer to nginx.

"accept_mutex off" is the default - http://nginx.org/r/accept_mutex

https://www.nginx.com/blog/performance-tuning-tips-tricks/ says

"""
We recommend keeping the default value (off) unless you have extensive
knowledge of your app’s performance and the opportunity to test under
a variety of conditions, but it can lead to inefficient use of system
resources if the volume of new connections is low. Changing the value
to on might be beneficial under some high loads.
"""

Your testing suggests that "accept_mutex on" does not help your use case.

So - don't set "accept_mutex on".

What further analysis is needed?

Cheers,

        f
--
Francis Daly        [hidden email]
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx