[Varnish] #808: Assert crash on load testing

Varnish varnish-bugs at varnish-cache.org
Tue Nov 2 14:52:42 CET 2010


#808: Assert crash on load testing
----------------------+-----------------------------------------------------
 Reporter:  diego     |       Owner:  phk  
     Type:  defect    |      Status:  new  
 Priority:  normal    |   Milestone:       
Component:  varnishd  |     Version:  trunk
 Severity:  normal    |    Keywords:       
----------------------+-----------------------------------------------------
Changes (by phk):

  * owner:  => phk
  * component:  build => varnishd


Old description:

> Error ocurred at both SVN 5430 and latest SVN 5487.
>
> To reproduce using httperf 0.9 and set num-calls to about 4000 and above.
> This is related to the session_workspace value. With 512KB, it will
> sustain/buffer 3600 requests/second. I have tested the session_workspace
> value and it directly correlates to how many calls can be made per keep-
> alive request before varnish asserts and restarts. Lowering the value
> lowers the number of num-calls httperf will be able send without crashing
> varnish. For example, using defaults, varnish can only sustain a few
> hundred almost simultaneous requests from a single connection.
>
> If varnish can somehow not assert but check its session memory usage and
> close the connection if reaching session workspace limit, it would be
> ideal as compared to the case now where varnish restarts.
>
> {{{
> httperf --server www.myserver.com --uri /  --num-conns 1 --num-calls 4000
> }}}
>
> Varnish startup line:
>
> {{{
> varnishd -f varnish_vcl.txt -a $IP:22201 -T 127.0.0.1:22201 -n /raid0 -h
> critbit -smalloc,8G -p thread_pools=2 -p thread_pool_min=100 -p
> thread_pool_max=500 -p thread_pool_add_delay=2 -p listen_depth=4096 -p
> session_linger=50/100/150 -p lru_interval=20 -p sess_workspace=512000
> }}}
>

> {{{
> Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22056) died signal=6
> Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22056) Panic message: Assert
> error in http_Write(), cache_http.c line 918:
> Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
> worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
> Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
> varnishd(http_Write+0x293) [0x420433]   0x426fab:
> varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
> 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
> [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
> /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
> /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaaac19008 {   fd
> = 12, id = 12, xid = 733244310,   client = 209.151.227.72 56196,   step =
> STP_DELIVER,   handling = deliver,   err_code = 200, err_reason = (null),
> restarts = 0, esis = 0   ws = 0x2aaaaac19080 {      id = "sess",
> {s,f,r,e} = {0x2aaaaac19cd8,+216,(nil),+65536},   },   http[req] = {
> ws = 0x2aaaaac19080[sess]
> Oct 29 06:18:57 kitty1 /raid0[21974]: child (22075) Started
> Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22075) said
> Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22075) said Child starts
> Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22075) died signal=6
> Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22075) Panic message: Assert
> error in http_Write(), cache_http.c line 918:
> Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
> worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
> Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
> varnishd(http_Write+0x293) [0x420433]   0x426fab:
> varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
> 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
> [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
> /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
> /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaab0af008 {   fd
> = 12, id = 12, xid = 227475721,   client = 209.151.227.72 57424,   step =
> STP_DELIVER,   handling = deliver,   restarts = 0, esis = 0   ws =
> 0x2aaaab0af080 {      id = "sess",     {s,f,r,e} =
> {0x2aaaab0afcd8,+216,(nil),+65536},   },   http[req] = {     ws =
> 0x2aaaab0af080[sess]       "GET",       "/",       "HTTP/1.
> Oct 29 06:19:47 kitty1 /raid0[21974]: child (22094) Started
> Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22094) said
> Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22094) said Child starts
> Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22094) died signal=6
> Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22094) Panic message: Assert
> error in http_Write(), cache_http.c line 918:
> Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
> worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
> Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
> varnishd(http_Write+0x293) [0x420433]   0x426fab:
> varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
> 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
> [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
> /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
> /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaaabe8008 {   fd
> = 14, id = 14, xid = 170289336,   client = 209.151.227.72 57483,   step =
> STP_DELIVER,   handling = deliver,   err_code = 200, err_reason = (null),
> restarts = 0, esis = 0   ws = 0x2aaaaabe8080 {      id = "sess",
> {s,f,r,e} = {0x2aaaaabe8cd8,+216,(nil),+65536},   },   http[req] = {
> ws = 0x2aaaaabe8080[sess]
> Oct 29 06:19:49 kitty1 /raid0[21974]: child (22113) Started
> Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22113) said
> Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22113) said Child starts
> Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22113) died signal=6
> Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22113) Panic message: Assert
> error in http_Write(), cache_http.c line 918:
> Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
> worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
> Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
> varnishd(http_Write+0x293) [0x420433]   0x426fab:
> varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
> 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
> [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
> /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
> /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaab336008 {   fd
> = 22, id = 22, xid = 161296516,   client = 209.151.227.72 57576,   step =
> STP_DELIVER,   handling = deliver,   err_code = 200, err_reason = (null),
> restarts = 0, esis = 0   ws = 0x2aaaab336080 {      id = "sess",
> {s,f,r,e} = {0x2aaaab336cd8,+216,(nil),+65536},   },   http[req] = {
> ws = 0x2aaaab336080[sess]
> Oct 29 06:19:53 kitty1 /raid0[21974]: child (22132) Started
> Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22132) said
> Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22132) said Child starts
>

> }}}

New description:

 Error ocurred at both SVN 5430 and latest SVN 5487.

 To reproduce using httperf 0.9 and set num-calls to about 4000 and above.
 This is related to the session_workspace value. With 512KB, it will
 sustain/buffer 3600 requests/second. I have tested the session_workspace
 value and it directly correlates to how many calls can be made per keep-
 alive request before varnish asserts and restarts. Lowering the value
 lowers the number of num-calls httperf will be able send without crashing
 varnish. For example, using defaults, varnish can only sustain a few
 hundred almost simultaneous requests from a single connection.

 If varnish can somehow not assert but check its session memory usage and
 close the connection if reaching session workspace limit, it would be
 ideal as compared to the case now where varnish restarts.

 {{{
 httperf --server www.myserver.com --uri /  --num-conns 1 --num-calls 4000
 }}}

 Varnish startup line:

 {{{
 varnishd -f varnish_vcl.txt -a $IP:22201 -T 127.0.0.1:22201 -n /raid0 -h
 critbit -smalloc,8G -p thread_pools=2 -p thread_pool_min=100 -p
 thread_pool_max=500 -p thread_pool_add_delay=2 -p listen_depth=4096 -p
 session_linger=50/100/150 -p lru_interval=20 -p sess_workspace=512000
 }}}


 {{{
 Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22056) died signal=6
 Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22056) Panic message:
 Assert error in http_Write(), cache_http.c line 918:
  Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true.
  thread = (cache-worker)
  ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
 Backtrace:
    0x424a46: varnishd [0x424a46]
    0x420433: varnishd(http_Write+0x293) [0x420433]
    0x426fab: varnishd(RES_WriteObj+0x12b) [0x426fab]
    0x413b7a: varnishd [0x413b7a]
    0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]
    0x426e08: varnishd [0x426e08]
    0x4260f7: varnishd [0x4260f7]
    0x2b5a67c2173d: /lib64/libpthread.so.0 [0x2b5a67c2173d]
    0x2b5a683a5d1d: /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d]
  sp = 0x2aaaaac19008 {
    fd = 12, id = 12, xid = 733244310,
    client = 209.151.227.72 56196,
    step = STP_DELIVER,
    handling = deliver,
    err_code = 200, err_reason = (null),
    restarts = 0, esis = 0
    ws = 0x2aaaaac19080 {
       id = "sess",
      {s,f,r,e} = {0x2aaaaac19cd8,+216,(nil),+65536},
    },
    http[req] = {
      ws = 0x2aaaaac19080[sess]
 Oct 29 06:18:57 kitty1 /raid0[21974]: child (22075) Started
 Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22075) said
 Oct 29 06:18:57 kitty1 /raid0[21974]: Child (22075) said Child starts
 Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22075) died signal=6
 Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22075) Panic message: Assert
 error in http_Write(), cache_http.c line 918:
 Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
 worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
 Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
 varnishd(http_Write+0x293) [0x420433]   0x426fab:
 varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
 [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
 /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
 /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaab0af008 {   fd =
 12, id = 12, xid = 227475721,   client = 209.151.227.72 57424,   step =
 STP_DELIVER,   handling = deliver,   restarts = 0, esis = 0   ws =
 0x2aaaab0af080 {      id = "sess",     {s,f,r,e} =
 {0x2aaaab0afcd8,+216,(nil),+65536},   },   http[req] = {     ws =
 0x2aaaab0af080[sess]       "GET",       "/",       "HTTP/1.
 Oct 29 06:19:47 kitty1 /raid0[21974]: child (22094) Started
 Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22094) said
 Oct 29 06:19:47 kitty1 /raid0[21974]: Child (22094) said Child starts
 Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22094) died signal=6
 Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22094) Panic message: Assert
 error in http_Write(), cache_http.c line 918:
 Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
 worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
 Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
 varnishd(http_Write+0x293) [0x420433]   0x426fab:
 varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
 [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
 /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
 /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaaabe8008 {   fd =
 14, id = 14, xid = 170289336,   client = 209.151.227.72 57483,   step =
 STP_DELIVER,   handling = deliver,   err_code = 200, err_reason = (null),
 restarts = 0, esis = 0   ws = 0x2aaaaabe8080 {      id = "sess",
 {s,f,r,e} = {0x2aaaaabe8cd8,+216,(nil),+65536},   },   http[req] = {
 ws = 0x2aaaaabe8080[sess]
 Oct 29 06:19:49 kitty1 /raid0[21974]: child (22113) Started
 Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22113) said
 Oct 29 06:19:49 kitty1 /raid0[21974]: Child (22113) said Child starts
 Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22113) died signal=6
 Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22113) Panic message: Assert
 error in http_Write(), cache_http.c line 918:
 Condition((hp->hd[HTTP_HDR_STATUS].b) != 0) not true. thread = (cache-
 worker) ident = Linux,2.6.18-164.11.1.el5,x86_64,-smalloc,-hcritbit,epoll
 Backtrace:   0x424a46: varnishd [0x424a46]   0x420433:
 varnishd(http_Write+0x293) [0x420433]   0x426fab:
 varnishd(RES_WriteObj+0x12b) [0x426fab]   0x413b7a: varnishd [0x413b7a]
 0x4148e9: varnishd(CNT_Session+0x369) [0x4148e9]   0x426e08: varnishd
 [0x426e08]   0x4260f7: varnishd [0x4260f7]   0x2b5a67c2173d:
 /lib64/libpthread.so.0 [0x2b5a67c2173d]   0x2b5a683a5d1d:
 /lib64/libc.so.6(clone+0x6d) [0x2b5a683a5d1d] sp = 0x2aaaab336008 {   fd =
 22, id = 22, xid = 161296516,   client = 209.151.227.72 57576,   step =
 STP_DELIVER,   handling = deliver,   err_code = 200, err_reason = (null),
 restarts = 0, esis = 0   ws = 0x2aaaab336080 {      id = "sess",
 {s,f,r,e} = {0x2aaaab336cd8,+216,(nil),+65536},   },   http[req] = {
 ws = 0x2aaaab336080[sess]
 Oct 29 06:19:53 kitty1 /raid0[21974]: child (22132) Started
 Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22132) said
 Oct 29 06:19:53 kitty1 /raid0[21974]: Child (22132) said Child starts


 }}}

--

-- 
Ticket URL: <http://www.varnish-cache.org/trac/ticket/808#comment:1>
Varnish <http://varnish-cache.org/>
The Varnish HTTP Accelerator




More information about the varnish-bugs mailing list