{"action":"created","issue":{"url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/77","repository_url":"https://api.github.com/repos/winshining/nginx-http-flv-module","labels_url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/77/labels{/name}","comments_url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/77/comments","events_url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/77/events","html_url":"https://github.com/winshining/nginx-http-flv-module/issues/77","id":369191822,"node_id":"MDU6SXNzdWUzNjkxOTE4MjI=","number":77,"title":"[ bug ] Slow response time","user":{"login":"invalidtask","id":35407932,"node_id":"MDQ6VXNlcjM1NDA3OTMy","avatar_url":"https://avatars0.githubusercontent.com/u/35407932?v=4","gravatar_id":"","url":"https://api.github.com/users/invalidtask","html_url":"https://github.com/invalidtask","followers_url":"https://api.github.com/users/invalidtask/followers","following_url":"https://api.github.com/users/invalidtask/following{/other_user}","gists_url":"https://api.github.com/users/invalidtask/gists{/gist_id}","starred_url":"https://api.github.com/users/invalidtask/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/invalidtask/subscriptions","organizations_url":"https://api.github.com/users/invalidtask/orgs","repos_url":"https://api.github.com/users/invalidtask/repos","events_url":"https://api.github.com/users/invalidtask/events{/privacy}","received_events_url":"https://api.github.com/users/invalidtask/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2018-10-11T15:59:22Z","updated_at":"2018-10-17T16:42:47Z","closed_at":null,"author_association":"NONE","body":"~~Edit: After observing resource usage of each worker, this may be caused by workers reaching 100% CPU usage. Much apologies for opening this issue without fully investigating. I am closing this issue.~~\r\n\r\nEdit 2: Experiencing this issue contrary to my previous edit message. Happening at 20% CPU and roughly 600 clients. \r\n\r\nEdit 3: I'm running an instance in debug mode, this seems to show up whenever there is a slow response time:\r\n\r\n`accept() not ready (11: Resource temporarily unavailable)`\r\n\r\nEdit 4: I have no idea if any of this info is relevant, my apologies if its not:\r\n\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357738\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:40:30 [debug] 25216#25216: *1284 SSL_write: 128\r\n> 2018/10/12 14:40:30 [debug] 25216#25216: *1284 SSL to write: 128\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357760\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:40:30 [debug] 25216#25216: *1284 SSL_write: 128\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357781\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357802\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357824\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357845\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357866\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357888\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357909\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357930\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357952\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357973\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31357994\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358016\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358037\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358058\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358080\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358101\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358122\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358144\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358165\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358186\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 flv live: HTTP drop message bufs='4096', priority='0'\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: skip non-key\r\n> 2018/10/12 14:39:58 [debug] 25222#25222: *1227 live: abs audio header timestamp=31358208\r\n\r\n\r\n### Expected behavior\r\nHTTP request to be returned quickly\r\n\r\n### Actual behavior\r\nIt seems there are client connections blocking/slowing down new requests. Specifically noticeable if a client is dropping a lot of frames (per the stat page under stream name). As a result, HTTP requests (as well as plain text HTTP) can take up to 15 seconds to respond and load. This doesn't happen across all processes, seems to only happen on processes with playback clients that drop a lot of frames.\r\n\r\n### Steps to reproduce the behavior \r\nI don't know how to replicate a client with a bad connection :(\r\n\r\nConfiguration file:\r\n```\r\nuser root;\r\nworker_processes 16;\r\nworker_cpu_affinity auto;\r\npid /run/nginx.pid;\r\nworker_rlimit_nofile 1048576;\r\n\r\nevents {\r\n    worker_connections 1048576;\r\n    multi_accept on;\r\n    use epoll;\r\n    accept_mutex on;\r\n}\r\nhttp {\r\n    include mime.types;\r\n    default_type application/octet-stream;\r\n    keepalive_timeout 3;\r\n    access_log off;\r\n    error_log off;\r\n    sendfile on;\r\n    server_tokens off;\r\n    gzip on;\r\n    server {\r\n        listen 80;\r\n        location / {\r\n            root /var/html/www;\r\n            index index.html;\r\n        }\r\n        error_page 500 502 503 504 /50x.html;\r\n        location = /50x.html {\r\n            root html;\r\n        }\r\n        location /live {\r\n            flv_live on; #open flv live streaming (subscribe)\r\n            chunked_transfer_encoding off; #open 'Transfer-Encoding: chunked' response\r\n        }\r\n    }\r\n}\r\n\r\nrtmp_auto_push on;\r\nrtmp_auto_push_reconnect 1s;\r\nrtmp_socket_dir /tmp;\r\n\r\nrtmp {\r\n    out_queue   4096;\r\n    out_cork    8;\r\n    max_streams 10240;\r\n    access_log  off;\r\n    server {\r\n        listen 1935;\r\n        application live {\r\n            live on;\r\n            deny publish all;\r\n            gop_cache off; #open GOP cache for low latency\r\n            pull rtmp://localhost/live;\r\n        }\r\n    }\r\n}\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/comments/430701999","html_url":"https://github.com/winshining/nginx-http-flv-module/issues/77#issuecomment-430701999","issue_url":"https://api.github.com/repos/winshining/nginx-http-flv-module/issues/77","id":430701999,"node_id":"MDEyOklzc3VlQ29tbWVudDQzMDcwMTk5OQ==","user":{"login":"HeyJupiter","id":42520467,"node_id":"MDQ6VXNlcjQyNTIwNDY3","avatar_url":"https://avatars2.githubusercontent.com/u/42520467?v=4","gravatar_id":"","url":"https://api.github.com/users/HeyJupiter","html_url":"https://github.com/HeyJupiter","followers_url":"https://api.github.com/users/HeyJupiter/followers","following_url":"https://api.github.com/users/HeyJupiter/following{/other_user}","gists_url":"https://api.github.com/users/HeyJupiter/gists{/gist_id}","starred_url":"https://api.github.com/users/HeyJupiter/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/HeyJupiter/subscriptions","organizations_url":"https://api.github.com/users/HeyJupiter/orgs","repos_url":"https://api.github.com/users/HeyJupiter/repos","events_url":"https://api.github.com/users/HeyJupiter/events{/privacy}","received_events_url":"https://api.github.com/users/HeyJupiter/received_events","type":"User","site_admin":false},"created_at":"2018-10-17T16:42:47Z","updated_at":"2018-10-17T16:42:47Z","author_association":"CONTRIBUTOR","body":"@winshining So how to reproduce the bug as \"muliti-processes mode enabled in finding the correct application when connect `command` is received\"? I've been testing the module always with the directive `woker_processes auto` enabled (nginx-1.13.10 & the latest nginx-http-flv-module) but it has been working perfectly for me.\r\nLooking forward to your reply cause I nearly used it in product environment."}}
{"actor":{"display_login":"HeyJupiter"}}