Hi Graham, On Wed, 14 Sep 2016, Graham Leggett wrote:
> On 06 Sep 2016, at 12:06 AM, Stefan Fritsch <s...@sfritsch.de> wrote: > > > in trunk, when having a lot of slow long running transfers, most of them > > seem > > to hog a thread and only a few of them go into async write completion mode. > > Compare this to 2.4, where many transfers are doing async write completion > > and > > only a small number of threads are busy. > > > > Is this a known issue? > > I’ve seen this before, but couldn’t reproduce it reliably. > > If you can catch a long running transfer can you get a stacktrace from > it? One possible option is that a bucket is insisting on being consumed > in one go and thus refuses to leave the handler hook and enter write > completion, the second option is that the bucket ends up in write > completion but blocks, and we would need to know why. > > There are still a number of filters out there that insist on swallowing > whole bucket brigades in one go. Any of these filters will prevent write > completion from working. This will show up in the stacktrace. Stack trace of a few such threads is below. I don't see anything besides the core output filter there. Maybe you see more. I have also included the list of loaded modules. From extra/ I have httpd-userdir.conf proxy-html.conf httpd-info.conf httpd-mpm.conf included. Apart from that, it's a somewhat outdated but unmodified default config. Cheers, Stefan Thread 5 (Thread 0x7f70c9a69700 (LWP 3398)): #0 0x00007f70daaea50d in poll () at ../sysdeps/unix/syscall-template.S:84 No locals. #1 0x00007f70db83c5d2 in apr_poll (aprset=0x7f70c9a68c20, num=1, nsds=0x7f70c9a68c0c, timeout=60000) at poll/unix/poll.c:120 i = 1 num_to_poll = 1 pollset = 0x7f70c9a68b60 #2 0x00000000004529b1 in send_brigade_blocking (c=0x7f70c825b348, bytes_written=0x7f70c8257a00, bb=0x7f70c8257658, s=0x7f70c825b0b0) at core_filters.c:633 nsds = 1 timeout = 60000000 pollset = {p = 0x7f70c8257028, desc_type = APR_POLL_SOCKET, reqevents = 4, rtnevents = 4, desc = {f = 0x7f70c825b0b0, s = 0x7f70c825b0b0}, client_data = 0x7f70c82576a8} rv = <optimized out> #3 ap_core_output_filter (f=0x7f70c8257830, bb=0x7f70c8257658) at core_filters.c:449 c = 0x7f70c825b348 net = 0x7f70c82577d8 ctx = 0x7f70c82579f0 flush_upto = 0x7f70c825a6e8 rv = <optimized out> loglevel = 4 #4 0x000000000043955f in ap_pass_brigade (bb=<optimized out>, next=0x7f70c8257830) at util_filter.c:610 e = <optimized out> #5 ap_filter_output_pending (c=0x7f70c825b348) at util_filter.c:985 f = 0x7f70c8257830 rindex = 0x7f70c82576a8 data_in_output_filters = -1 #6 0x0000000000435ef0 in ap_run_output_pending (c=c@entry=0x7f70c825b348) at mpm_common.c:122 pHook = <optimized out> n = 0 rv = -1 #7 0x00007f70ce5da6fc in process_socket (my_thread_num=3, my_child_num=1, cs=0x7f70c825b2b8, sock=0x7f70c825b0b0, p=0x7f70c825b028, thd=0x7f70dc57cee8) at event.c:1152 not_complete_yet = <optimized out> c = 0x7f70c825b348 sbh = 0x7f70c825b2a0 conn_id = <optimized out> rc = <optimized out> #8 worker_thread (thd=0x7f70dc57cee8, dummy=<optimized out>) at event.c:2261 csd = 0x7f70c825b0b0 cs = 0x0 te = 0x0 ptrans = 0x7f70c825b028 ti = <optimized out> process_slot = 1 thread_slot = 3 rv = <optimized out> is_idle = 0 #9 0x00007f70db842488 in dummy_worker (opaque=0x7f70dc57cee8) at threadproc/unix/thread.c:142 thread = 0x7f70dc57cee8 #10 0x00007f70dafb4464 in start_thread (arg=0x7f70c9a69700) at pthread_create.c:333 __res = <optimized out> pd = 0x7f70c9a69700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140122396202752, 6480505367792406515, 0, 140122429770751, 0, 140122711343168, -6408919108241895437, -6408951309539651597}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = { prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> pagesize_m1 = <optimized out> sp = <optimized out> freesize = <optimized out> __PRETTY_FUNCTION__ = "start_thread" #11 0x00007f70daaf397f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105 No locals. Thread 3 (Thread 0x7f70caa6b700 (LWP 3394)): #0 0x00007f70daaea50d in poll () at ../sysdeps/unix/syscall-template.S:84 No locals. #1 0x00007f70db83c5d2 in apr_poll (aprset=0x7f70caa6ac20, num=1, nsds=0x7f70caa6ac0c, timeout=60000) at poll/unix/poll.c:120 i = 1 num_to_poll = 1 pollset = 0x7f70caa6ab60 #2 0x00000000004529b1 in send_brigade_blocking (c=0x7f70dc506348, bytes_written=0x7f70dc502a00, bb=0x7f70dc502658, s=0x7f70dc5060b0) at core_filters.c:633 nsds = 1 timeout = 60000000 pollset = {p = 0x7f70dc502028, desc_type = APR_POLL_SOCKET, reqevents = 4, rtnevents = 4, desc = {f = 0x7f70dc5060b0, s = 0x7f70dc5060b0}, client_data = 0x7f70dc5026a8} rv = <optimized out> #3 ap_core_output_filter (f=0x7f70dc502830, bb=0x7f70dc502658) at core_filters.c:449 c = 0x7f70dc506348 net = 0x7f70dc5027d8 ctx = 0x7f70dc5029f0 flush_upto = 0x7f70dc5056e8 rv = <optimized out> loglevel = 4 #4 0x000000000043955f in ap_pass_brigade (bb=<optimized out>, next=0x7f70dc502830) at util_filter.c:610 e = <optimized out> #5 ap_filter_output_pending (c=0x7f70dc506348) at util_filter.c:985 f = 0x7f70dc502830 rindex = 0x7f70dc5026a8 data_in_output_filters = -1 #6 0x0000000000435ef0 in ap_run_output_pending (c=c@entry=0x7f70dc506348) at mpm_common.c:122 pHook = <optimized out> n = 0 rv = -1 #7 0x00007f70ce5da6fc in process_socket (my_thread_num=1, my_child_num=1, cs=0x7f70dc5062b8, sock=0x7f70dc5060b0, p=0x7f70dc506028, thd=0x7f70dc57ce88) at event.c:1152 not_complete_yet = <optimized out> c = 0x7f70dc506348 sbh = 0x7f70dc5062a0 conn_id = <optimized out> rc = <optimized out> #8 worker_thread (thd=0x7f70dc57ce88, dummy=<optimized out>) at event.c:2261 csd = 0x7f70dc5060b0 cs = 0x0 te = 0x0 ptrans = 0x7f70dc506028 ti = <optimized out> process_slot = 1 thread_slot = 1 rv = <optimized out> is_idle = 0 #9 0x00007f70db842488 in dummy_worker (opaque=0x7f70dc57ce88) at threadproc/unix/thread.c:142 thread = 0x7f70dc57ce88 #10 0x00007f70dafb4464 in start_thread (arg=0x7f70caa6b700) at pthread_create.c:333 __res = <optimized out> pd = 0x7f70caa6b700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140122412988160, 6480505367792406515, 0, 140122429770751, 0, 140122711343168, -6408916910292381709, -6408951309539651597}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = { prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> pagesize_m1 = <optimized out> sp = <optimized out> freesize = <optimized out> __PRETTY_FUNCTION__ = "start_thread" #11 0x00007f70daaf397f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105 No locals. Thread 2 (Thread 0x7f70cb26c700 (LWP 3391)): #0 0x00007f70daaea50d in poll () at ../sysdeps/unix/syscall-template.S:84 No locals. #1 0x00007f70db83c5d2 in apr_poll (aprset=0x7f70cb26bc20, num=1, nsds=0x7f70cb26bc0c, timeout=60000) at poll/unix/poll.c:120 i = 1 num_to_poll = 1 pollset = 0x7f70cb26bb60 #2 0x00000000004529b1 in send_brigade_blocking (c=0x7f70dc514348, bytes_written=0x7f70dc510a00, bb=0x7f70dc510658, s=0x7f70dc5140b0) at core_filters.c:633 nsds = 1 timeout = 60000000 pollset = {p = 0x7f70dc510028, desc_type = APR_POLL_SOCKET, reqevents = 4, rtnevents = 4, desc = {f = 0x7f70dc5140b0, s = 0x7f70dc5140b0}, client_data = 0x7f70dc5106a8} rv = <optimized out> #3 ap_core_output_filter (f=0x7f70dc510830, bb=0x7f70dc510658) at core_filters.c:449 c = 0x7f70dc514348 net = 0x7f70dc5107d8 ctx = 0x7f70dc5109f0 flush_upto = 0x7f70dc5136e8 rv = <optimized out> loglevel = 4 #4 0x000000000043955f in ap_pass_brigade (bb=<optimized out>, next=0x7f70dc510830) at util_filter.c:610 e = <optimized out> #5 ap_filter_output_pending (c=0x7f70dc514348) at util_filter.c:985 f = 0x7f70dc510830 rindex = 0x7f70dc5106a8 data_in_output_filters = 0 #6 0x0000000000435ef0 in ap_run_output_pending (c=c@entry=0x7f70dc514348) at mpm_common.c:122 pHook = <optimized out> n = 0 rv = -1 #7 0x00007f70ce5da6fc in process_socket (my_thread_num=0, my_child_num=1, cs=0x7f70dc5142b8, sock=0x7f70dc5140b0, p=0x7f70dc514028, thd=0x7f70dc57ce58) at event.c:1152 not_complete_yet = <optimized out> c = 0x7f70dc514348 sbh = 0x7f70dc5142a0 conn_id = <optimized out> rc = <optimized out> #8 worker_thread (thd=0x7f70dc57ce58, dummy=<optimized out>) at event.c:2261 csd = 0x7f70dc5140b0 cs = 0x0 te = 0x0 ptrans = 0x7f70dc514028 ti = <optimized out> process_slot = 1 thread_slot = 0 rv = <optimized out> is_idle = 0 #9 0x00007f70db842488 in dummy_worker (opaque=0x7f70dc57ce58) at threadproc/unix/thread.c:142 thread = 0x7f70dc57ce58 #10 0x00007f70dafb4464 in start_thread (arg=0x7f70cb26c700) at pthread_create.c:333 __res = <optimized out> pd = 0x7f70cb26c700 now = <optimized out> unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140122421380864, 6480505367792406515, 0, 140122429770751, 0, 140122711343168, -6408913612294369293, -6408951309539651597}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = { prev = 0x0, cleanup = 0x0, canceltype = 0}}} not_first_call = <optimized out> pagesize_m1 = <optimized out> sp = <optimized out> freesize = <optimized out> __PRETTY_FUNCTION__ = "start_thread" #11 0x00007f70daaf397f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:105 No locals. LoadModule authn_file_module modules/mod_authn_file.so LoadModule authn_dbm_module modules/mod_authn_dbm.so LoadModule authn_anon_module modules/mod_authn_anon.so LoadModule authn_dbd_module modules/mod_authn_dbd.so LoadModule authn_socache_module modules/mod_authn_socache.so LoadModule authn_core_module modules/mod_authn_core.so LoadModule authz_host_module modules/mod_authz_host.so LoadModule authz_groupfile_module modules/mod_authz_groupfile.so LoadModule authz_user_module modules/mod_authz_user.so LoadModule authz_dbm_module modules/mod_authz_dbm.so LoadModule authz_owner_module modules/mod_authz_owner.so LoadModule authz_dbd_module modules/mod_authz_dbd.so LoadModule authz_core_module modules/mod_authz_core.so LoadModule authnz_fcgi_module modules/mod_authnz_fcgi.so LoadModule access_compat_module modules/mod_access_compat.so LoadModule auth_basic_module modules/mod_auth_basic.so LoadModule auth_form_module modules/mod_auth_form.so LoadModule auth_digest_module modules/mod_auth_digest.so LoadModule allowmethods_module modules/mod_allowmethods.so LoadModule allowhandlers_module modules/mod_allowhandlers.so LoadModule socache_shmcb_module modules/mod_socache_shmcb.so LoadModule reqtimeout_module modules/mod_reqtimeout.so LoadModule request_module modules/mod_request.so LoadModule include_module modules/mod_include.so LoadModule filter_module modules/mod_filter.so LoadModule substitute_module modules/mod_substitute.so LoadModule sed_module modules/mod_sed.so LoadModule charset_lite_module modules/mod_charset_lite.so LoadModule xml2enc_module modules/mod_xml2enc.so LoadModule proxy_html_module modules/mod_proxy_html.so LoadModule mime_module modules/mod_mime.so LoadModule syslog_module modules/mod_syslog.so LoadModule log_config_module modules/mod_log_config.so LoadModule logio_module modules/mod_logio.so LoadModule lua_module modules/mod_lua.so LoadModule env_module modules/mod_env.so LoadModule expires_module modules/mod_expires.so LoadModule headers_module modules/mod_headers.so LoadModule ident_module modules/mod_ident.so LoadModule usertrack_module modules/mod_usertrack.so LoadModule unique_id_module modules/mod_unique_id.so LoadModule setenvif_module modules/mod_setenvif.so LoadModule version_module modules/mod_version.so LoadModule remoteip_module modules/mod_remoteip.so LoadModule proxy_module modules/mod_proxy.so LoadModule proxy_connect_module modules/mod_proxy_connect.so LoadModule proxy_ftp_module modules/mod_proxy_ftp.so LoadModule proxy_http_module modules/mod_proxy_http.so LoadModule proxy_fcgi_module modules/mod_proxy_fcgi.so LoadModule proxy_scgi_module modules/mod_proxy_scgi.so LoadModule proxy_fdpass_module modules/mod_proxy_fdpass.so LoadModule proxy_wstunnel_module modules/mod_proxy_wstunnel.so LoadModule proxy_ajp_module modules/mod_proxy_ajp.so LoadModule proxy_balancer_module modules/mod_proxy_balancer.so LoadModule proxy_express_module modules/mod_proxy_express.so LoadModule session_module modules/mod_session.so LoadModule session_cookie_module modules/mod_session_cookie.so LoadModule session_crypto_module modules/mod_session_crypto.so LoadModule session_dbd_module modules/mod_session_dbd.so LoadModule slotmem_shm_module modules/mod_slotmem_shm.so LoadModule slotmem_plain_module modules/mod_slotmem_plain.so LoadModule policy_module modules/mod_policy.so LoadModule lbmethod_byrequests_module modules/mod_lbmethod_byrequests.so LoadModule lbmethod_bytraffic_module modules/mod_lbmethod_bytraffic.so LoadModule lbmethod_bybusyness_module modules/mod_lbmethod_bybusyness.so LoadModule lbmethod_heartbeat_module modules/mod_lbmethod_heartbeat.so LoadModule mpm_event_module modules/mod_mpm_event.so LoadModule unixd_module modules/mod_unixd.so LoadModule status_module modules/mod_status.so LoadModule autoindex_module modules/mod_autoindex.so LoadModule asis_module modules/mod_asis.so LoadModule info_module modules/mod_info.so LoadModule suexec_module modules/mod_suexec.so LoadModule vhost_alias_module modules/mod_vhost_alias.so LoadModule negotiation_module modules/mod_negotiation.so LoadModule dir_module modules/mod_dir.so LoadModule userdir_module modules/mod_userdir.so LoadModule alias_module modules/mod_alias.so LoadModule rewrite_module modules/mod_rewrite.so