[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