httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stefan Fritsch ...@sfritsch.de>
Subject Re: Async write completion broken in trunk?
Date Sun, 18 Sep 2016 08:57:58 GMT
Hi Graham,

On Wed, 14 Sep 2016, Graham Leggett wrote:

> On 06 Sep 2016, at 12:06 AM, Stefan Fritsch <sf@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
Mime
  • Unnamed multipart/mixed (inline, None, 0 bytes)
View raw message