Mailing List Archive

#1675: Condition((vbc->in_waiter) != 0) not true.
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------
Reporter: zaterio@… | Type: defect
Status: new | Priority: normal
Milestone: Varnish 4.0 release | Component: varnishd
Version: trunk | Severity: normal
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------
previously we only had panic according to ticket # 1628.
then update to trunk version a281a10 and added a 90 GB file backend for
some domains.
with new version #1628 has not been detected, but this new condition
appeared:


varnish> panic.show
200
Last panic at: Sat, 07 Feb 2015 06:56:13 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 96:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision a281a10
ident =
Linux,3.2.0-4-amd64,x86_64,-smalloc,-sfile,-smalloc,-hclassic,epoll
Backtrace:
0x4356e4: pan_ic+0x134
0x415b54: tcp_handle+0x254
0x466fe9: Wait_Handle+0x89
0x467881: vwe_thread+0xf1
0x7fd62d5b8b50: libpthread.so.0(+0x6b50) [0x7fd62d5b8b50]
0x7fd62d30270d: libc.so.6(clone+0x6d) [0x7fd62d30270d]




varnishd -V
varnishd (varnish-trunk revision a281a10)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS

DAEMON_OPTS="-a XXX.XXX.XXX.XXX:80, \
-T XXX.XXX.XXX.XXX:6082 \
-f /etc/varnish/default.vcl \
-h classic,16383 \
-s ram1=malloc,10G \
-s disk1=file,/varnishcache/varnish.bin,90G \
-p thread_pools=2 \
-p thread_pool_min=100 \
-p thread_pool_max=3000 \
-p thread_pool_add_delay=2 \
-p auto_restart=on \
-p listen_depth=2048 \
-p ping_interval=3 \
-p cli_timeout=25 \
-p ban_dups=on"

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner:
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by coredump):

I got two servers and I had them panic within 10 minutes of each other.
Both are using a 65G malloc storage. Both panic'ed around 165k objects,
what I think may be a coincidence but worth mentioning.

Last panic at: Fri, 13 Feb 2015 02:27:20 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 96:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision 17dae8e
ident = Linux,3.2.0-61-generic,x86_64,-smalloc,-smalloc,-hcritbit,epoll
Backtrace:
0x4344fa: pan_ic+0x13a
0x4145e4: tcp_handle+0x264
0x466949: Wait_Handle+0x89
0x467202: vwe_thread+0x112
0x7f47107d5e9a: libpthread.so.0(+0x7e9a) [0x7f47107d5e9a]
0x7f47105032ed: libc.so.6(clone+0x6d) [0x7f47105032ed]

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

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------
Changes (by phk):

* owner: => phk


--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:2>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------
Description changed by phk:

Old description:

> previously we only had panic according to ticket # 1628.
> then update to trunk version a281a10 and added a 90 GB file backend for
> some domains.
> with new version #1628 has not been detected, but this new condition
> appeared:
>

> varnish> panic.show
> 200
> Last panic at: Sat, 07 Feb 2015 06:56:13 GMT
> Assert error in tcp_handle(), cache/cache_backend_tcp.c line 96:
> Condition((vbc->in_waiter) != 0) not true.
> thread = (cache-epoll)
> version = varnish-trunk revision a281a10
> ident =
> Linux,3.2.0-4-amd64,x86_64,-smalloc,-sfile,-smalloc,-hclassic,epoll
> Backtrace:
> 0x4356e4: pan_ic+0x134
> 0x415b54: tcp_handle+0x254
> 0x466fe9: Wait_Handle+0x89
> 0x467881: vwe_thread+0xf1
> 0x7fd62d5b8b50: libpthread.so.0(+0x6b50) [0x7fd62d5b8b50]
> 0x7fd62d30270d: libc.so.6(clone+0x6d) [0x7fd62d30270d]
>

>

> varnishd -V
> varnishd (varnish-trunk revision a281a10)
> Copyright (c) 2006 Verdens Gang AS
> Copyright (c) 2006-2015 Varnish Software AS
>
> DAEMON_OPTS="-a XXX.XXX.XXX.XXX:80, \
> -T XXX.XXX.XXX.XXX:6082 \
> -f /etc/varnish/default.vcl \
> -h classic,16383 \
> -s ram1=malloc,10G \
> -s disk1=file,/varnishcache/varnish.bin,90G \
> -p thread_pools=2 \
> -p thread_pool_min=100 \
> -p thread_pool_max=3000 \
> -p thread_pool_add_delay=2 \
> -p auto_restart=on \
> -p listen_depth=2048 \
> -p ping_interval=3 \
> -p cli_timeout=25 \
> -p ban_dups=on"

New description:

previously we only had panic according to ticket # 1628.
then update to trunk version a281a10 and added a 90 GB file backend for
some domains.
with new version #1628 has not been detected, but this new condition
appeared:

{{{
varnish> panic.show
200
Last panic at: Sat, 07 Feb 2015 06:56:13 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 96:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision a281a10
ident =
Linux,3.2.0-4-amd64,x86_64,-smalloc,-sfile,-smalloc,-hclassic,epoll
Backtrace:
0x4356e4: pan_ic+0x134
0x415b54: tcp_handle+0x254
0x466fe9: Wait_Handle+0x89
0x467881: vwe_thread+0xf1
0x7fd62d5b8b50: libpthread.so.0(+0x6b50) [0x7fd62d5b8b50]
0x7fd62d30270d: libc.so.6(clone+0x6d) [0x7fd62d30270d]




varnishd -V
varnishd (varnish-trunk revision a281a10)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS

DAEMON_OPTS="-a XXX.XXX.XXX.XXX:80, \
-T XXX.XXX.XXX.XXX:6082 \
-f /etc/varnish/default.vcl \
-h classic,16383 \
-s ram1=malloc,10G \
-s disk1=file,/varnishcache/varnish.bin,90G \
-p thread_pools=2 \
-p thread_pool_min=100 \
-p thread_pool_max=3000 \
-p thread_pool_add_delay=2 \
-p auto_restart=on \
-p listen_depth=2048 \
-p ping_interval=3 \
-p cli_timeout=25 \
-p ban_dups=on"
}}}

--

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:3>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

Sorry about the delay in replying...

This is related to some new work I've been doing, to put a "waiter" on the
unused backend connections. It is not related to the storage changes.

I will try to track this down.

Any chance you can capture a varnishlog output for me ? (Preferably
"varnislog -g raw")

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:4>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

I have attached varnishlog output, while varnishlog was logging (raw),
varnishadm reported the following error:

Last panic at: Mon, 02 Mar 2015 15:01:59 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 9
6:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision 5fe64d6
ident = Linux,3.2.0-0.bpo.1-amd64,x86_64,-junix,-smalloc,-smal
loc,-hclassic,epoll
Backtrace:
0x433c9a: pan_ic+0x14a
0x4142e5: tcp_handle+0x255
0x465b20: Wait_Handle+0x90
0x466db0: vwe_thread+0x100
0x7f0e85fca8ca: libpthread.so.0(+0x68ca) [0x7f0e85fca8ca]
0x7f0e85d31b6d: libc.so.6(clone+0x6d) [0x7f0e85d31b6d]




Regards

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:5>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: new
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

I think I may have spotted something, and I've tried to fix it, but I'm
not entirely sure.

Can I get you to test -trunk with or later than
bbac365619c995096d6a690bf531227e095424d4 ?

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:6>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------
Changes (by slink):

* status: new => needinfo


--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:7>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

Dear phk, sorry the delay, i was in holiday:

now running:

varnishd -V
varnishd (varnish-trunk revision 63bf572)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS

I will report any issue.

Regards

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:8>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

panic.show
200
Last panic at: Wed, 25 Mar 2015 14:49:02 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 95:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision 63bf572
ident =
Linux,2.6.32-5-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,epoll
Backtrace:
0x433f8a: pan_ic+0x14a
0x4140fd: tcp_handle+0x3bd
0x465ed0: Wait_Handle+0x90
0x467160: vwe_thread+0x100
0x7fd69f5358ca: libpthread.so.0(+0x68ca) [0x7fd69f5358ca]
0x7fd69f29cb6d: libc.so.6(clone+0x6d) [0x7fd69f29cb6d]

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:9>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by lkarsten):

Hit this one today, on an installation with almost no traffic.

Not seeing it on any of the fryer runs.

{{{
Last panic at: Mon, 27 Apr 2015 14:26:37 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 94:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision 6e7c5cf
ident =
Linux,3.13.0-49-generic,x86_64,-junix,-smalloc,-smalloc,-hcritbit,epoll
Backtrace:
0x439dc5: pan_backtrace+0x19
0x43a1ad: pan_ic+0x299
0x414226: tcp_handle+0x12e
0x4794d8: Wait_Handle+0x2b3
0x479c2d: vwe_eev+0xde
0x479dee: vwe_thread+0x11b
0x7f7060a9e182: libpthread.so.0(+0x8182) [0x7f7060a9e182]
0x7f70607cb47d: libc.so.6(clone+0x6d) [0x7f70607cb47d]

}}}

upgraded it to latest master.

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:10>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

Still repeatable in latest master:
{{{
varnishd (varnish-trunk revision d0012bd)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

{{{
varnish> panic.show
200
Last panic at: Tue, 12 May 2015 12:33:17 GMT
Assert error in tcp_handle(), cache/cache_backend_tcp.c line 94:
Condition((vbc->in_waiter) != 0) not true.
thread = (cache-epoll)
version = varnish-trunk revision d0012bd
ident =
Linux,3.2.0-4-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,epoll
Backtrace:
0x433224: pan_ic+0x134
0x415bed: tcp_handle+0x38d
0x463279: Wait_Handle+0x89
0x463a1a: vwe_thread+0xfa
0x7f05516c9b50: libpthread.so.0(+0x6b50) [0x7f05516c9b50]
0x7f055141395d: libc.so.6(clone+0x6d) [0x7f055141395d]
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:11>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

the following command stops right after the panic:

{{{
varnishlog -i Debug -g raw > /home/out.log
}}}


FD States

{{{
cat /home/salidarwa.txt |grep Handler|awk '{print $8" "$9" "$10" "$11"
"$12" "$13" "$14" "$15}'|sort|uniq -c|sort -n
}}}

{{{
1 in_w 0 state 0x2 ev 2 have_been 1"
1 in_w 1 state 0x2 ev 1 have_been 0"
1 in_w 1 state 0x4 ev 1 have_been 1"
2 in_w 1 state 0x1 ev 2 have_been 0"
2 in_w 1 state 0x2 ev 1 have_been 1"
2 in_w 1 state 0x4 ev 2 have_been 0"
4 in_w 1 state 0x8 ev 1 have_been 1"
33 in_w 1 state 0x8 ev 2 have_been 1"
125 in_w 1 state 0x2 ev 2 have_been 0"
1081 in_w 1 state 0x2 ev 2 have_been 1"
}}}


the next state is suspect:

{{{
1 in_w 0 state 0x2 ev 2 have_been 1
}}}

* just one case vbc->in_waiter = 0.
* the log entry is the last in /home/out.log

It is associated with FD 105:

{{{
cat /home/out.log |grep "fd 105"
}}}


{{{
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Close fd 105 in_w 1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x8 ev 2
have_been 1"
0 Debug - "------> New fd 105"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 0"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 2
have_been 1"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Close fd 105 in_w 1"
0 Debug - "------> Handler fd 105 in_w 1 state 0x8 ev 2
have_been 1"
0 Debug - "------> New fd 105"
0 Debug - "------> Recycle fd 105 in_w 0"
0 Debug - "------> Recycle fd 105 Wait_Enter"
0 Debug - "------> Steal fd 105 state 0x1"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Recycle fd 105 in_w 1"
0 Debug - "------> Steal fd 105 state 0x4"
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 1
have_been 0"
0 Debug - "------> Handler fd 105 in_w 0 state 0x2 ev 2
have_been 1"
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:12>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

{{{
0 Debug - "------> Handler fd 105 in_w 1 state 0x2 ev 1 have_been
0"
0 Debug - "------> Handler fd 105 in_w 0 state 0x2 ev 2 have_been
1"
}}}

both status are VBC_STATE_USED, the first status is changed to the second
status by:

{{{
case VBC_STATE_USED:
vbc->in_waiter = 0;
vbc->have_been_in_waiter = 1;
break;
}}}


And then, when the second handler hits:

{{{
AN(vbc->in_waiter);
}}}

Fails because in_waiter = 0.

vbc->in_waiter = 0; must be changed to non zero value in case
VBC_STATE_USED.

In my scenario states "in_w = 0" are rare, and when they appear varnish
dies

For example handlers after 2 hours running, shows no "in_waiter = 0":

{{{
cat /home/out.log |grep Handler|awk '{print $8" "$9" "$10" "$11" "$12"
"$13" "$14" "$15}'|sort|uniq -c|sort -n
2 in_w 1 state 0x4 ev 1 have_been 0"
3 in_w 1 state 0x4 ev 1 have_been 1"
14 in_w 1 state 0x1 ev 2 have_been 0"
18 in_w 1 state 0x8 ev 2 have_been 0"
235 in_w 1 state 0x8 ev 2 have_been 1"
809 in_w 1 state 0x2 ev 2 have_been 0"
8863 in_w 1 state 0x2 ev 2 have_been 1"
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:13>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

Can I get you try the "poll" waiter ?

You need to add

-p waiter=poll

to the command line.

(I suspect this is related to the epoll() waiter only.)

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:14>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

I have commited a change to the way the epoll waiter works.

Please also try that (-trunk) if you can.

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:15>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

After 12h varnish uptime.

OBS: average varnish uptime 7h.

{{{
varnishd -V
varnishd (varnish-trunk revision ade0db0)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

{{{
DAEMON_OPTS="-a XXX.XXX.XXX.XXX:80, \
-T 127.0.0.1:6082 \
-f /etc/varnish/default.vcl \
-h classic,16383 \
-s malloc,6G \
-p thread_pools=2 \
-p thread_pool_min=500 \
-p thread_pool_max=3000 \
-p thread_pool_add_delay=2 \
-p auto_restart=on \
-p ping_interval=3 \
-p send_timeout=5000 \
-p workspace_session=1M \
-p cli_timeout=25 \
-p http_gzip_support=off \
-p tcp_keepalive_time=600 \
-p listen_depth=8192 \
-p cli_buffer=32k \
-p cli_limit=96k \
-p waiter=poll \
-p ban_dups=on"
}}}

Log file 1
{{{
varnishlog -i Debug -g raw > /home/out.log
}}}

Log file 2
{{{
varnishlog -i BackendClose -i Backend -i BackendOpen -i BackendReuse -i
Backend_health -i FetchError -i WorkThread > /home/salida2.log
}}}

{{{
varnishadm panic.show
Child has not panicked or panic has been cleared
Command failed with error code 300
}}}

{{{
cat /home/out.log |grep "Acceptor poll space increased"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
0 Debug - "Acceptor poll space increased to 1024"
}}}

{{{
cat /home/out.log |grep "POLL Evict"|wc -l
606873
}}}

{{{
cat /home/out.log |grep "POLL Inject"|wc -l
607083
}}}

{{{
cat /home/out.log |grep "POLL Handle"|wc -l
74503781
}}}

{{{
cat /home/out.log |grep "Handler stolen"|wc -l
0
}}}

{{{
cat /home/out.log |grep "Recycle fd"|cut -d" " -f26-|sort|uniq -c|sort -n
69015 in_w 0"
69015 Wait_Enter"
79659 in_w 1"
}}}

{{{
cat /home/out.log |grep "Handler fd"|cut -d" " -f26-|sort|uniq -c|sort -n
2 in_w 1 state 0x8 ev 1 have_been 1"
3 in_w 1 state 0x1 ev 1 have_been 0"
3 in_w 1 state 0x1 ev 2 have_been 1"
4 in_w 1 state 0x2 ev 1 have_been 0"
14 in_w 1 state 0x4 ev 1 have_been 0"
36 in_w 1 state 0x1 ev 1 have_been 1"
39 in_w 1 state 0x2 ev 1 have_been 1"
48 in_w 1 state 0x8 ev 2 have_been 1"
129 in_w 1 state 0x4 ev 2 have_been 1"
241 in_w 1 state 0x4 ev 2 have_been 0"
608 in_w 1 state 0x4 ev 1 have_been 1"
1115 in_w 1 state 0x1 ev 2 have_been 0"
6450 in_w 1 state 0x2 ev 2 have_been 0"
61311 in_w 1 state 0x2 ev 2 have_been 1"
}}}

{{{
cat /home/out.log |grep "Close fd"|cut -d" " -f26-|sort|uniq -c|sort -n
58 in_w 1"
7713 in_w 0"
}}}

{{{
cat /home/out.log |grep "Steal fd"|cut -d" " -f26-|sort|uniq -c|sort -n
68847 state 0x1"
78665 state 0x4"
}}}

{{{
cat /home/out.log |grep "No new fd"|wc -l
0
}}}

{{{
cat /home/salida2.log |grep FetchError |sort|uniq -c|sort -n
1 - FetchError Resource temporarily unavailable
6 - FetchError straight insufficient bytes
58 - FetchError http first read error: EOF
84 - FetchError no backend connection
}}}

{{{
varnishstat -1
MAIN.uptime 45109 1.00 Child process uptime
MAIN.sess_conn 620241 13.75 Sessions accepted
MAIN.sess_drop 0 0.00 Sessions dropped
MAIN.sess_fail 0 0.00 Session accept failures
MAIN.client_req_400 0 0.00 Client requests received,
subject to 400 errors
MAIN.client_req_417 0 0.00 Client requests received,
subject to 417 errors
MAIN.client_req 1582499 35.08 Good client requests
received
MAIN.cache_hit 1395139 30.93 Cache hits
MAIN.cache_hitpass 0 0.00 Cache hits for pass
MAIN.cache_miss 163918 3.63 Cache misses
MAIN.backend_conn 0 0.00 Backend conn. success
MAIN.backend_unhealthy 84 0.00 Backend conn. not
attempted
MAIN.backend_busy 0 0.00 Backend conn. too many
MAIN.backend_fail 0 0.00 Backend conn. failures
MAIN.backend_reuse 344540 7.64 Backend conn. reuses
MAIN.backend_recycle 347536 7.70 Backend conn. recycles
MAIN.backend_retry 134 0.00 Backend conn. retry
MAIN.fetch_head 0 0.00 Fetch no body (HEAD)
MAIN.fetch_length 254150 5.63 Fetch with Length
MAIN.fetch_chunked 1796 0.04 Fetch chunked
MAIN.fetch_eof 0 0.00 Fetch EOF
MAIN.fetch_bad 0 0.00 Fetch bad T-E
MAIN.fetch_none 4683 0.10 Fetch no body
MAIN.fetch_1xx 0 0.00 Fetch no body (1xx)
MAIN.fetch_204 0 0.00 Fetch no body (204)
MAIN.fetch_304 86952 1.93 Fetch no body (304)
MAIN.fetch_failed 14 0.00 Fetch failed (all causes)
MAIN.fetch_no_thread 0 0.00 Fetch failed (no thread)
MAIN.pools 2 . Number of thread pools
MAIN.threads 1000 . Total number of threads
MAIN.threads_limited 0 0.00 Threads hit max
MAIN.threads_created 1000 0.02 Threads created
MAIN.threads_destroyed 0 0.00 Threads destroyed
MAIN.threads_failed 0 0.00 Thread creation failed
MAIN.thread_queue_len 0 . Length of session queue
MAIN.busy_sleep 2371 0.05 Number of requests sent
to sleep on busy objhdr
MAIN.busy_wakeup 2371 0.05 Number of requests woken
after sleep on busy objhdr
MAIN.busy_killed 0 0.00 Number of requests killed
after sleep on busy objhdr
MAIN.sess_queued 0 0.00 Sessions queued for
thread
MAIN.sess_dropped 0 0.00 Sessions dropped for
thread
MAIN.n_object 4991 . object structs made
MAIN.n_vampireobject 0 . unresurrected objects
MAIN.n_objectcore 5810 . objectcore structs made
MAIN.n_objecthead 5860 . objecthead structs made
MAIN.n_waitinglist 981 . waitinglist structs made
MAIN.n_backend 5 . Number of backends
MAIN.n_expired 41683 . Number of expired objects
MAIN.n_lru_nuked 117276 . Number of LRU nuked
objects
MAIN.n_lru_moved 307416 . Number of LRU moved
objects
MAIN.losthdr 0 0.00 HTTP header overflows
MAIN.s_sess 620241 13.75 Total sessions seen
MAIN.s_req 1582499 35.08 Total requests seen
MAIN.s_pipe 19130 0.42 Total pipe sessions seen
MAIN.s_pass 5 0.00 Total pass-ed requests
seen
MAIN.s_fetch 163923 3.63 Total backend fetches
initiated
MAIN.s_synth 4307 0.10 Total synthethic
responses made
MAIN.s_req_hdrbytes 684657640 15177.85 Request header bytes
MAIN.s_req_bodybytes 0 0.00 Request body bytes
MAIN.s_resp_hdrbytes 548015036 12148.69 Response header bytes
MAIN.s_resp_bodybytes 1036430331602 22976131.85 Response body bytes
MAIN.s_pipe_hdrbytes 7462368 165.43 Pipe request header bytes
MAIN.s_pipe_in 128 0.00 Piped bytes from client
MAIN.s_pipe_out 99654156717 2209185.68 Piped bytes to client
MAIN.sess_closed 107237 2.38 Session Closed
MAIN.sess_closed_err 490513 10.87 Session Closed with error
MAIN.sess_pipeline 0 0.00 Session Pipeline
MAIN.sess_readahead 0 0.00 Session Read Ahead
MAIN.sess_herd 1458429 32.33 Session herd
MAIN.sc_rem_close 43219 0.96 Session OK REM_CLOSE
MAIN.sc_req_close 4225 0.09 Session OK REQ_CLOSE
MAIN.sc_req_http10 0 0.00 Session Err REQ_HTTP10
MAIN.sc_rx_bad 0 0.00 Session Err RX_BAD
MAIN.sc_rx_body 0 0.00 Session Err RX_BODY
MAIN.sc_rx_junk 0 0.00 Session Err RX_JUNK
MAIN.sc_rx_overflow 0 0.00 Session Err RX_OVERFLOW
MAIN.sc_rx_timeout 490513 10.87 Session Err RX_TIMEOUT
MAIN.sc_tx_pipe 19121 0.42 Session OK TX_PIPE
MAIN.sc_tx_error 0 0.00 Session Err TX_ERROR
MAIN.sc_tx_eof 0 0.00 Session OK TX_EOF
MAIN.sc_resp_close 62654 1.39 Session OK RESP_CLOSE
MAIN.sc_overload 0 0.00 Session Err OVERLOAD
MAIN.sc_pipe_overflow 0 0.00 Session Err PIPE_OVERFLOW
MAIN.sc_range_short 0 0.00 Session Err RANGE_SHORT
MAIN.shm_records 289059599 6408.02 SHM records
MAIN.shm_writes 165872322 3677.14 SHM writes
MAIN.shm_flushes 200 0.00 SHM flushes due to
overflow
MAIN.shm_cont 156978 3.48 SHM MTX contention
MAIN.shm_cycles 107 0.00 SHM cycles through buffer
MAIN.backend_req 347680 7.71 Backend requests made
MAIN.n_vcl 1 0.00 Number of loaded VCLs in
total
MAIN.n_vcl_avail 1 0.00 Number of VCLs available
MAIN.n_vcl_discard 0 0.00 Number of discarded VCLs
MAIN.bans 1 . Count of bans
MAIN.bans_completed 1 . Number of bans marked
'completed'
MAIN.bans_obj 0 . Number of bans using
obj.*
MAIN.bans_req 0 . Number of bans using
req.*
MAIN.bans_added 1 0.00 Bans added
MAIN.bans_deleted 0 0.00 Bans deleted
MAIN.bans_tested 0 0.00 Bans tested against
objects (lookup)
MAIN.bans_obj_killed 0 0.00 Objects killed by bans
(lookup)
MAIN.bans_lurker_tested 0 0.00 Bans tested against
objects (lurker)
MAIN.bans_tests_tested 0 0.00 Ban tests tested against
objects (lookup)
MAIN.bans_lurker_tests_tested 0 0.00 Ban tests tested
against objects (lurker)
MAIN.bans_lurker_obj_killed 0 0.00 Objects killed by
bans (lurker)
MAIN.bans_dups 0 0.00 Bans superseded by
other bans
MAIN.bans_lurker_contention 0 0.00 Lurker gave way
for lookup
MAIN.bans_persisted_bytes 13 . Bytes used by the
persisted ban lists
MAIN.bans_persisted_fragmentation 0 . Extra bytes in
persisted ban lists due to fragmentation
MAIN.n_purges 0 . Number of
purge operations executed
MAIN.n_obj_purged 0 . Number of
purged objects
MAIN.exp_mailed 648638 14.38 Number of
objects mailed to expiry thread
MAIN.exp_received 648638 14.38 Number of
objects received by expiry thread
MAIN.hcb_nolock 0 0.00 HCB Lookups
without lock
MAIN.hcb_lock 0 0.00 HCB Lookups
with lock
MAIN.hcb_insert 0 0.00 HCB Inserts
MAIN.esi_errors 0 0.00 ESI parse
errors (unlock)
MAIN.esi_warnings 0 0.00 ESI parse
warnings (unlock)
MAIN.vmods 2 . Loaded VMODs
MAIN.n_gzip 0 0.00 Gzip
operations
MAIN.n_gunzip 0 0.00 Gunzip
operations
MAIN.vsm_free 971488 . Free VSM space
MAIN.vsm_used 83963120 . Used VSM space
MAIN.vsm_cooling 0 . Cooling VSM
space
MAIN.vsm_overflow 0 . Overflow VSM
space
MAIN.vsm_overflowed 0 0.00 Overflowed VSM
space
MGT.uptime 45109 1.00 Management
process uptime
MGT.child_start 1 0.00 Child process
started
MGT.child_exit 0 0.00 Child process
normal exit
MGT.child_stop 0 0.00 Child process
unexpected exit
MGT.child_died 0 0.00 Child process
died (signal)
MGT.child_dump 0 0.00 Child process
core dumped
MGT.child_panic 0 0.00 Child process
panic
MEMPOOL.busyobj.live 37 . In use
MEMPOOL.busyobj.pool 18 . In Pool
MEMPOOL.busyobj.sz_wanted 65536 . Size requested
MEMPOOL.busyobj.sz_actual 65504 . Size allocated
MEMPOOL.busyobj.allocs 366813 8.13 Allocations
MEMPOOL.busyobj.frees 366776 8.13 Frees
MEMPOOL.busyobj.recycle 366662 8.13 Recycled from
pool
MEMPOOL.busyobj.timeout 28276 0.63 Timed out from
pool
MEMPOOL.busyobj.toosmall 0 0.00 Too small to
recycle
MEMPOOL.busyobj.surplus 0 0.00 Too many for
pool
MEMPOOL.busyobj.randry 151 0.00 Pool ran dry
MEMPOOL.req0.live 72 . In use
MEMPOOL.req0.pool 31 . In Pool
MEMPOOL.req0.sz_wanted 65536 . Size requested
MEMPOOL.req0.sz_actual 65504 . Size allocated
MEMPOOL.req0.allocs 791478 17.55 Allocations
MEMPOOL.req0.frees 791406 17.54 Frees
MEMPOOL.req0.recycle 790891 17.53 Recycled from
pool
MEMPOOL.req0.timeout 30123 0.67 Timed out from
pool
MEMPOOL.req0.toosmall 0 0.00 Too small to
recycle
MEMPOOL.req0.surplus 103 0.00 Too many for
pool
MEMPOOL.req0.randry 587 0.01 Pool ran dry
MEMPOOL.sess0.live 246 . In use
MEMPOOL.sess0.pool 12 . In Pool
MEMPOOL.sess0.sz_wanted 1048576 . Size requested
MEMPOOL.sess0.sz_actual 1048544 . Size allocated
MEMPOOL.sess0.allocs 310037 6.87 Allocations
MEMPOOL.sess0.frees 309791 6.87 Frees
MEMPOOL.sess0.recycle 309915 6.87 Recycled from
pool
MEMPOOL.sess0.timeout 30751 0.68 Timed out from
pool
MEMPOOL.sess0.toosmall 0 0.00 Too small to
recycle
MEMPOOL.sess0.surplus 0 0.00 Too many for
pool
MEMPOOL.sess0.randry 122 0.00 Pool ran dry
MEMPOOL.req1.live 71 . In use
MEMPOOL.req1.pool 37 . In Pool
MEMPOOL.req1.sz_wanted 65536 . Size requested
MEMPOOL.req1.sz_actual 65504 . Size allocated
MEMPOOL.req1.allocs 796368 17.65 Allocations
MEMPOOL.req1.frees 796297 17.65 Frees
MEMPOOL.req1.recycle 795817 17.64 Recycled from
pool
MEMPOOL.req1.timeout 30183 0.67 Timed out from
pool
MEMPOOL.req1.toosmall 0 0.00 Too small to
recycle
MEMPOOL.req1.surplus 33 0.00 Too many for
pool
MEMPOOL.req1.randry 551 0.01 Pool ran dry
MEMPOOL.sess1.live 262 . In use
MEMPOOL.sess1.pool 9 . In Pool
MEMPOOL.sess1.sz_wanted 1048576 . Size requested
MEMPOOL.sess1.sz_actual 1048544 . Size allocated
MEMPOOL.sess1.allocs 310241 6.88 Allocations
MEMPOOL.sess1.frees 309979 6.87 Frees
MEMPOOL.sess1.recycle 310078 6.87 Recycled from
pool
MEMPOOL.sess1.timeout 30717 0.68 Timed out from
pool
MEMPOOL.sess1.toosmall 0 0.00 Too small to
recycle
MEMPOOL.sess1.surplus 0 0.00 Too many for
pool
MEMPOOL.sess1.randry 163 0.00 Pool ran dry
SMA.s0.c_req 2879399 63.83 Allocator
requests
SMA.s0.c_fail 1851290 41.04 Allocator
failures
SMA.s0.c_bytes 230747070537 5115322.23 Bytes
allocated
SMA.s0.c_freed 224306392497 4972541.90 Bytes freed
SMA.s0.g_alloc 21083 . Allocations
outstanding
SMA.s0.g_bytes 6440678040 . Bytes
outstanding
SMA.s0.g_space 1772904 . Bytes
available
SMA.Transient.c_req 4477 0.10 Allocator
requests
SMA.Transient.c_fail 0 0.00 Allocator
failures
SMA.Transient.c_bytes 4976123 110.31 Bytes
allocated
SMA.Transient.c_freed 4976123 110.31 Bytes freed
SMA.Transient.g_alloc 0 . Allocations
outstanding
SMA.Transient.g_bytes 0 . Bytes
outstanding
SMA.Transient.g_space 0 . Bytes
available
VBE.boot.live.happy 18446744073709551615 . Happy
health probes
VBE.boot.live.bereq_hdrbytes 70786367 1569.23 Request header
bytes
VBE.boot.live.bereq_bodybytes 0 0.00 Request body
bytes
VBE.boot.live.beresp_hdrbytes 70551340 1564.02 Response
header bytes
VBE.boot.live.beresp_bodybytes 44906673308 995514.72 Response body
bytes
VBE.boot.live.pipe_hdrbytes 0 0.00 Pipe request
header bytes
VBE.boot.live.pipe_out 0 0.00 Piped bytes to
backend
VBE.boot.live.pipe_in 0 0.00 Piped bytes
from backend
VBE.boot.live.conn 214924 . Concurrent
connections to backend
VBE.boot.live.req 214921 4.76 Backend
requests sent
VBE.boot.vod_cache.happy 18446744073709551615 . Happy
health probes
VBE.boot.vod_cache.bereq_hdrbytes 57031720 1264.31 Request header
bytes
VBE.boot.vod_cache.bereq_bodybytes 0 0.00 Request body
bytes
VBE.boot.vod_cache.beresp_hdrbytes 47879808 1061.42 Response
header bytes
VBE.boot.vod_cache.beresp_bodybytes 185635292265 4115260.64 Response
body bytes
VBE.boot.vod_cache.pipe_hdrbytes 6448338 142.95 Pipe request
header bytes
VBE.boot.vod_cache.pipe_out 128 0.00 Piped bytes
to backend
VBE.boot.vod_cache.pipe_in 99654156717 2209185.68 Piped bytes
from backend
VBE.boot.vod_cache.conn 148304 . Concurrent
connections to backend
VBE.boot.vod_cache.req 148304 3.29 Backend
requests sent
VBE.boot.m3u82.happy 18446744073709551615 .
Happy health probes
VBE.boot.m3u82.bereq_hdrbytes 270673 6.00 Request
header bytes
VBE.boot.m3u82.bereq_bodybytes 0 0.00 Request body
bytes
VBE.boot.m3u82.beresp_hdrbytes 149275 3.31 Response
header bytes
VBE.boot.m3u82.beresp_bodybytes 299164 6.63 Response
body bytes
VBE.boot.m3u82.pipe_hdrbytes 0 0.00 Pipe request
header bytes
VBE.boot.m3u82.pipe_out 0 0.00 Piped bytes
to backend
VBE.boot.m3u82.pipe_in 0 0.00 Piped bytes
from backend
VBE.boot.m3u82.conn 853 . Concurrent
connections to backend
VBE.boot.m3u82.req 853 0.02 Backend
requests sent
VBE.boot.m3u87.happy 18446744073709551615 .
Happy health probes
VBE.boot.m3u87.bereq_hdrbytes 288667 6.40 Request
header bytes
VBE.boot.m3u87.bereq_bodybytes 0 0.00 Request body
bytes
VBE.boot.m3u87.beresp_hdrbytes 159333 3.53 Response
header bytes
VBE.boot.m3u87.beresp_bodybytes 319356 7.08 Response
body bytes
VBE.boot.m3u87.pipe_hdrbytes 0 0.00 Pipe request
header bytes
VBE.boot.m3u87.pipe_out 0 0.00 Piped bytes
to backend
VBE.boot.m3u87.pipe_in 0 0.00 Piped bytes
from backend
VBE.boot.m3u87.conn 921 . Concurrent
connections to backend
VBE.boot.m3u87.req 921 0.02 Backend
requests sent
VBE.boot.chvm3u8.happy 18446744073709551615 .
Happy health probes
VBE.boot.chvm3u8.bereq_hdrbytes 687101 15.23 Request
header bytes
VBE.boot.chvm3u8.bereq_bodybytes 0 0.00 Request body
bytes
VBE.boot.chvm3u8.beresp_hdrbytes 565899 12.55 Response
header bytes
VBE.boot.chvm3u8.beresp_bodybytes 241656 5.36 Response
body bytes
VBE.boot.chvm3u8.pipe_hdrbytes 0 0.00 Pipe request
header bytes
VBE.boot.chvm3u8.pipe_out 0 0.00 Piped bytes
to backend
VBE.boot.chvm3u8.pipe_in 0 0.00 Piped bytes
from backend
VBE.boot.chvm3u8.conn 1861 . Concurrent
connections to backend
VBE.boot.chvm3u8.req 1861 0.04 Backend
requests sent
LCK.sms.creat 0 0.00 Created
locks
LCK.sms.destroy 0 0.00 Destroyed
locks
LCK.sms.locks 0 0.00 Lock
Operations
LCK.smp.creat 0 0.00 Created
locks
LCK.smp.destroy 0 0.00 Destroyed
locks
LCK.smp.locks 0 0.00 Lock
Operations
LCK.sma.creat 2 0.00 Created
locks
LCK.sma.destroy 0 0.00 Destroyed
locks
LCK.sma.locks 3895379 86.35 Lock
Operations
LCK.smf.creat 0 0.00 Created
locks
LCK.smf.destroy 0 0.00 Destroyed
locks
LCK.smf.locks 0 0.00 Lock
Operations
LCK.hsl.creat 0 0.00 Created
locks
LCK.hsl.destroy 0 0.00 Destroyed
locks
LCK.hsl.locks 0 0.00 Lock
Operations
LCK.hcb.creat 0 0.00 Created
locks
LCK.hcb.destroy 0 0.00 Destroyed
locks
LCK.hcb.locks 0 0.00 Lock
Operations
LCK.hcl.creat 16383 0.36 Created
locks
LCK.hcl.destroy 0 0.00 Destroyed
locks
LCK.hcl.locks 3113169 69.01 Lock
Operations
LCK.vcl.creat 1 0.00 Created
locks
LCK.vcl.destroy 0 0.00 Destroyed
locks
LCK.vcl.locks 748115 16.58 Lock
Operations
LCK.sessmem.creat 0 0.00 Created
locks
LCK.sessmem.destroy 0 0.00 Destroyed
locks
LCK.sessmem.locks 0 0.00 Lock
Operations
LCK.sess.creat 620189 13.75 Created
locks
LCK.sess.destroy 619769 13.74 Destroyed
locks
LCK.sess.locks 0 0.00 Lock
Operations
LCK.wstat.creat 1 0.00 Created
locks
LCK.wstat.destroy 0 0.00 Destroyed
locks
LCK.wstat.locks 2467837 54.71 Lock
Operations
LCK.herder.creat 0 0.00 Created
locks
LCK.herder.destroy 0 0.00 Destroyed
locks
LCK.herder.locks 0 0.00 Lock
Operations
LCK.wq.creat 3 0.00 Created
locks
LCK.wq.destroy 0 0.00 Destroyed
locks
LCK.wq.locks 5831768 129.28 Lock
Operations
LCK.objhdr.creat 164797 3.65 Created
locks
LCK.objhdr.destroy 158935 3.52 Destroyed
locks
LCK.objhdr.locks 9557275 211.87 Lock
Operations
LCK.exp.creat 1 0.00 Created
locks
LCK.exp.destroy 0 0.00 Destroyed
locks
LCK.exp.locks 2361804 52.36 Lock
Operations
LCK.lru.creat 2 0.00 Created
locks
LCK.lru.destroy 0 0.00 Destroyed
locks
LCK.lru.locks 1647109 36.51 Lock
Operations
LCK.cli.creat 1 0.00 Created
locks
LCK.cli.destroy 0 0.00 Destroyed
locks
LCK.cli.locks 15043 0.33 Lock
Operations
LCK.ban.creat 1 0.00 Created
locks
LCK.ban.destroy 0 0.00 Destroyed
locks
LCK.ban.locks 838238 18.58 Lock
Operations
LCK.vbp.creat 0 0.00 Created
locks
LCK.vbp.destroy 0 0.00 Destroyed
locks
LCK.vbp.locks 0 0.00 Lock
Operations
LCK.backend.creat 15 0.00 Created
locks
LCK.backend.destroy 0 0.00 Destroyed
locks
LCK.backend.locks 1664985 36.91 Lock
Operations
LCK.vcapace.creat 1 0.00 Created
locks
LCK.vcapace.destroy 0 0.00 Destroyed
locks
LCK.vcapace.locks 0 0.00 Lock
Operations
LCK.nbusyobj.creat 0 0.00 Created
locks
LCK.nbusyobj.destroy 0 0.00 Destroyed
locks
LCK.nbusyobj.locks 0 0.00 Lock
Operations
LCK.busyobj.creat 366800 8.13 Created
locks
LCK.busyobj.destroy 366776 8.13 Destroyed
locks
LCK.busyobj.locks 9789231 217.01 Lock
Operations
LCK.mempool.creat 5 0.00 Created
locks
LCK.mempool.destroy 0 0.00 Destroyed
locks
LCK.mempool.locks 5574321 123.57 Lock
Operations
LCK.vxid.creat 1 0.00 Created
locks
LCK.vxid.destroy 0 0.00 Destroyed
locks
LCK.vxid.locks 986 0.02 Lock
Operations
LCK.pipestat.creat 1 0.00 Created
locks
LCK.pipestat.destroy 0 0.00 Destroyed
locks
LCK.pipestat.locks 19122 0.42 Lock
Operations
LCK.misc.creat 1 0.00 Created
locks
LCK.misc.destroy 0 0.00 Destroyed
locks
LCK.misc.locks 318126 7.05 Lock
Operations
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:16>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

So using the poll waiter stabilizes it ? That's very valuable
information.

Can I get you to try the changes I did to the epoll waiter yesterday ?

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:17>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

'''waiter: poll.'''

{{{
varnishd -V
varnishd (varnish-trunk revision ade0db0)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

new panic:

{{{
varnishadm panic.show
Last panic at: Fri, 15 May 2015 03:51:17 GMT
Assert error in vwp_inject(), waiter/cache_waiter_poll.c line 100:
Condition((vwp->pollfd[fd].revents) == 0) not true.
thread = (cache-poll)
version = varnish-trunk revision ade0db0
ident = Linux,3.2.0-4-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,poll
Backtrace:
0x4331f4: pan_ic+0x134
0x46425d: vwp_inject+0x18d
0x463331: Wait_Handle+0x171
0x463cb0: vwp_main+0x1e0
0x7f04eff5ab50: libpthread.so.0(+0x6b50) [0x7f04eff5ab50]
0x7f04efca495d: libc.so.6(clone+0x6d) [0x7f04efca495d]
}}}

I have attached a file with the last 10000 log lines.

using waiter poll varnish is more stable, the average uptime is 12h.

I will try this exact configuration, but epoll.

{{{
cat /varnishcache/out2.log |grep "Handler fd"|cut -d" " -f26-|sort|uniq
-c|sort -n
1 in_w 1 state 0x8 ev 1 have_been 0"
8 in_w 1 state 0x1 ev 2 have_been 1"
10 in_w 1 state 0x8 ev 1 have_been 1"
11 in_w 1 state 0x1 ev 1 have_been 0"
17 in_w 1 state 0x2 ev 1 have_been 0"
23 in_w 1 state 0x8 ev 2 have_been 0"
27 in_w 1 state 0x4 ev 1 have_been 0"
85 in_w 1 state 0x1 ev 1 have_been 1"
145 in_w 1 state 0x2 ev 1 have_been 1"
373 in_w 1 state 0x4 ev 2 have_been 1"
459 in_w 1 state 0x8 ev 2 have_been 1"
595 in_w 1 state 0x4 ev 2 have_been 0"
1498 in_w 1 state 0x4 ev 1 have_been 1"
2927 in_w 1 state 0x1 ev 2 have_been 0"
2977 in_w 1 state 0x2 ev 2 have_been 0"
141019 in_w 1 state 0x2 ev 2 have_been 1"
}}}

{{{
varnishadm param.show
acceptor_sleep_decay 0.9 (default)
acceptor_sleep_incr 0.001 [seconds] (default)
acceptor_sleep_max 0.050 [seconds] (default)
auto_restart on [bool] (default)
ban_dups on [bool] (default)
ban_lurker_age 60.000 [seconds] (default)
ban_lurker_batch 1000 (default)
ban_lurker_sleep 0.010 [seconds] (default)
between_bytes_timeout 60.000 [seconds] (default)
busyobj_worker_cache off [bool] (default)
cc_command "exec gcc -std=gnu99 -g -O2 -Wall -Werror -Wno-
error=unused-result -pthread -fpic -shared -Wl,-x -o %o %s" (default)
cli_buffer 32k [bytes]
cli_limit 96k [bytes]
cli_timeout 25.000 [seconds]
clock_skew 10 [seconds] (default)
connect_timeout 3.500 [seconds] (default)
critbit_cooloff 180.000 [seconds] (default)
debug none (default)
default_grace 10.000 [seconds] (default)
default_keep 0.000 [seconds] (default)
default_ttl 120.000 [seconds] (default)
feature none (default)
fetch_chunksize 16k [bytes] (default)
fetch_maxchunksize 0.25G [bytes] (default)
first_byte_timeout 60.000 [seconds] (default)
gzip_buffer 32k [bytes] (default)
gzip_level 6 (default)
gzip_memlevel 8 (default)
http_gzip_support off [bool]
http_max_hdr 64 [header lines] (default)
http_range_support on [bool] (default)
http_req_hdr_len 8k [bytes] (default)
http_req_size 32k [bytes] (default)
http_resp_hdr_len 8k [bytes] (default)
http_resp_size 32k [bytes] (default)
idle_send_timeout 60.000 [seconds] (default)
listen_depth 8192 [connections]
lru_interval 2.000 [seconds] (default)
max_esi_depth 5 [levels] (default)
max_restarts 4 [restarts] (default)
max_retries 4 [retries] (default)
nuke_limit 50 [allocations] (default)
pcre_match_limit 10000 (default)
pcre_match_limit_recursion 10000 (default)
ping_interval 3 [seconds] (default)
pipe_timeout 60.000 [seconds] (default)
pool_req 10,100,10 (default)
pool_sess 10,100,10 (default)
pool_vbo 10,100,10 (default)
prefer_ipv6 off [bool] (default)
rush_exponent 3 [requests per request] (default)
send_timeout 5000.000 [seconds]
session_max 100000 [sessions] (default)
shm_reclen 255b [bytes] (default)
shortlived 10.000 [seconds] (default)
sigsegv_handler off [bool] (default)
syslog_cli_traffic on [bool] (default)
tcp_keepalive_intvl 75.000 [seconds] (default)
tcp_keepalive_probes 9 [probes] (default)
tcp_keepalive_time 600.000 [seconds]
thread_pool_add_delay 2.000 [seconds]
thread_pool_destroy_delay 1.000 [seconds] (default)
thread_pool_fail_delay 0.200 [seconds] (default)
thread_pool_max 3000 [threads]
thread_pool_min 500 [threads]
thread_pool_stack 48k [bytes] (default)
thread_pool_timeout 300.000 [seconds] (default)
thread_pools 2 [pools] (default)
thread_queue_limit 20 (default)
thread_stats_rate 10 [requests] (default)
timeout_idle 10.000 [seconds]
timeout_linger 0.050 [seconds] (default)
vcc_allow_inline_c off [bool] (default)
vcc_err_unref on [bool] (default)
vcc_unsafe_path on [bool] (default)
vcl_cooldown 600.000 [seconds] (default)
vcl_dir /usr/local/varnish-trunk-ade0db/etc/varnish
(default)
vmod_dir /usr/local/varnish-trunk-
ade0db/lib/varnish/vmods (default)
vsl_buffer 4k [bytes] (default)
vsl_mask -VCL_trace,-WorkThread,-Hash,-VfpAcct (default)
vsl_reclen 255b [bytes] (default)
vsl_space 80M [bytes] (default)
vsm_space 1M [bytes] (default)
waiter poll (possible values: epoll, poll)
workspace_backend 64k [bytes] (default)
workspace_client 64k [bytes] (default)
workspace_session 1M [bytes]
workspace_thread 2k [bytes] (default)
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:18>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

And now with '''epoll waiter''':

very unstable, two minutes of uptime.

new panic:

{{{
varnishadm panic.show
Last panic at: Fri, 15 May 2015 16:03:23 GMT
Assert error in vwe_inject(), waiter/cache_waiter_epoll.c line 76:
Condition((epoll_ctl(vwe->epfd, 1, wp->fd, &ev)) == 0) not true.
errno = 17 (File exists)
thread = (cache-epoll)
version = varnish-trunk revision ade0db0
ident =
Linux,3.2.0-4-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,epoll
Backtrace:
0x4331f4: pan_ic+0x134
0x46365a: vwe_inject+0x9a
0x463331: Wait_Handle+0x171
0x4639e7: vwe_thread+0x147
0x7f954fe30b50: libpthread.so.0(+0x6b50) [0x7f954fe30b50]
0x7f954fb7a95d: libc.so.6(clone+0x6d) [0x7f954fb7a95d]
}}}

{{{
varnishd -V
varnishd (varnish-trunk revision ade0db0)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

{{{
varnishadm param.show
acceptor_sleep_decay 0.9 (default)
acceptor_sleep_incr 0.001 [seconds] (default)
acceptor_sleep_max 0.050 [seconds] (default)
auto_restart on [bool] (default)
ban_dups on [bool] (default)
ban_lurker_age 60.000 [seconds] (default)
ban_lurker_batch 1000 (default)
ban_lurker_sleep 0.010 [seconds] (default)
between_bytes_timeout 60.000 [seconds] (default)
busyobj_worker_cache off [bool] (default)
cc_command "exec gcc -std=gnu99 -g -O2 -Wall -Werror -Wno-
error=unused-result -pthread -fpic -shared -Wl,-x -o %o %s" (default)
cli_buffer 32k [bytes]
cli_limit 96k [bytes]
cli_timeout 25.000 [seconds]
clock_skew 10 [seconds] (default)
connect_timeout 3.500 [seconds] (default)
critbit_cooloff 180.000 [seconds] (default)
debug none (default)
default_grace 10.000 [seconds] (default)
default_keep 0.000 [seconds] (default)
default_ttl 120.000 [seconds] (default)
feature none (default)
fetch_chunksize 16k [bytes] (default)
fetch_maxchunksize 0.25G [bytes] (default)
first_byte_timeout 60.000 [seconds] (default)
gzip_buffer 32k [bytes] (default)
gzip_level 6 (default)
gzip_memlevel 8 (default)
http_gzip_support off [bool]
http_max_hdr 64 [header lines] (default)
http_range_support on [bool] (default)
http_req_hdr_len 8k [bytes] (default)
http_req_size 32k [bytes] (default)
http_resp_hdr_len 8k [bytes] (default)
http_resp_size 32k [bytes] (default)
idle_send_timeout 60.000 [seconds] (default)
listen_depth 8192 [connections]
lru_interval 2.000 [seconds] (default)
max_esi_depth 5 [levels] (default)
max_restarts 4 [restarts] (default)
max_retries 4 [retries] (default)
nuke_limit 50 [allocations] (default)
pcre_match_limit 10000 (default)
pcre_match_limit_recursion 10000 (default)
ping_interval 3 [seconds] (default)
pipe_timeout 60.000 [seconds] (default)
pool_req 10,100,10 (default)
pool_sess 10,100,10 (default)
pool_vbo 10,100,10 (default)
prefer_ipv6 off [bool] (default)
rush_exponent 3 [requests per request] (default)
send_timeout 5000.000 [seconds]
session_max 100000 [sessions] (default)
shm_reclen 255b [bytes] (default)
shortlived 10.000 [seconds] (default)
sigsegv_handler off [bool] (default)
syslog_cli_traffic on [bool] (default)
tcp_keepalive_intvl 75.000 [seconds] (default)
tcp_keepalive_probes 9 [probes] (default)
tcp_keepalive_time 600.000 [seconds]
thread_pool_add_delay 2.000 [seconds]
thread_pool_destroy_delay 1.000 [seconds] (default)
thread_pool_fail_delay 0.200 [seconds] (default)
thread_pool_max 3000 [threads]
thread_pool_min 500 [threads]
thread_pool_stack 48k [bytes] (default)
thread_pool_timeout 300.000 [seconds] (default)
thread_pools 2 [pools] (default)
thread_queue_limit 20 (default)
thread_stats_rate 10 [requests] (default)
timeout_idle 5.000 [seconds] (default)
timeout_linger 0.050 [seconds] (default)
vcc_allow_inline_c off [bool] (default)
vcc_err_unref on [bool] (default)
vcc_unsafe_path on [bool] (default)
vcl_cooldown 600.000 [seconds] (default)
vcl_dir /usr/local/varnish-trunk-ade0db/etc/varnish
(default)
vmod_dir /usr/local/varnish-trunk-
ade0db/lib/varnish/vmods (default)
vsl_buffer 4k [bytes] (default)
vsl_mask -VCL_trace,-WorkThread,-Hash,-VfpAcct (default)
vsl_reclen 255b [bytes] (default)
vsl_space 80M [bytes] (default)
vsm_space 1M [bytes] (default)
waiter epoll (possible values: epoll, poll) (default)
workspace_backend 64k [bytes] (default)
workspace_client 64k [bytes] (default)
workspace_session 1M [bytes]
workspace_thread 2k [bytes] (default)
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:19>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

I really don't understand this error, but I'll keep working until I do :-)

I fixed a race in the backend/tcp_pool code, and while I'm far from
certain that it has anything to do with this, it could explain some of the
weirder behaviours we have seen, so if you have time to test
eb8f35bd79206ff489b895ffb2dc3fb07cabfce5 I'd really appreciate it.

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:20>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

'''Installation Procedure:'''
{{{
git clone https://github.com/varnish/Varnish-Cache.git
git reset --hard eb8f35bd79206ff489b895ffb2dc3fb07cabfce5
./autogen.sh
./configure --prefix=/usr/local/varnish-eb8f35b
make
make install
cat /etc/ld.so.conf.d/varnish.conf
/usr/local/varnish-eb8f35b/lib/
/usr/local/varnish-eb8f35b/lib/varnish/
ldconfig
cp /usr/local/varnish-eb8f35b/sbin/* /usr/sbin/
cp /usr/local/varnish-eb8f35b/bin/* /usr/bin/
/etc/init.d/varnish start
}}}

'''lsof |grep varnishd |grep lib|awk '{print $10}'|sort|uniq -c|sort
-n|awk '{print $2}''''
{{{
/lib/x86_64-linux-gnu/ld-2.13.so
/lib/x86_64-linux-gnu/libc-2.13.so
/lib/x86_64-linux-gnu/libdl-2.13.so
/lib/x86_64-linux-gnu/libm-2.13.so
/lib/x86_64-linux-gnu/libnsl-2.13.so
/lib/x86_64-linux-gnu/libnss_compat-2.13.so
/lib/x86_64-linux-gnu/libnss_files-2.13.so
/lib/x86_64-linux-gnu/libnss_nis-2.13.so
/lib/x86_64-linux-gnu/libpcre.so.3.13.1
/lib/x86_64-linux-gnu/libpthread-2.13.so
/lib/x86_64-linux-gnu/librt-2.13.so
/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
/usr/local/varnish-eb8f35b/lib/varnish/libvarnishcompat.so
/usr/local/varnish-eb8f35b/lib/varnish/libvarnish.so
/usr/local/varnish-eb8f35b/lib/varnish/libvcc.so
/usr/local/varnish-eb8f35b/lib/varnish/libvgz.so
/usr/local/varnish-eb8f35b/lib/varnish/vmods/libvmod_directors.so
/usr/local/varnish-eb8f35b/lib/varnish/vmods/libvmod_std.so
}}}

'''varnishd -V'''
{{{
varnishd (varnish-trunk revision eb8f35b)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

'''testing epoll (panic every 3 min):'''
{{{
varnishadm panic.show
Last panic at: Mon, 18 May 2015 12:19:14 GMT
Assert error in vwe_inject(), waiter/cache_waiter_epoll.c line 76:
Condition((epoll_ctl(vwe->epfd, 1, wp->fd, &ev)) == 0) not true.
errno = 17 (File exists)
thread = (cache-epoll)
version = varnish-trunk revision eb8f35b
ident =
Linux,3.2.0-4-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,epoll
Backtrace:
0x4334e4: pan_ic+0x134
0x4638ca: vwe_inject+0x9a
0x4635a1: Wait_Handle+0x171
0x463c57: vwe_thread+0x147
0x7f2018de6b50: libpthread.so.0(+0x6b50) [0x7f2018de6b50]
0x7f2018b3095d: libc.so.6(clone+0x6d) [0x7f2018b3095d]
}}}

{{{
varnishadm panic.show
Last panic at: Mon, 18 May 2015 12:22:17 GMT
Assert error in vwe_inject(), waiter/cache_waiter_epoll.c line 76:
Condition((epoll_ctl(vwe->epfd, 1, wp->fd, &ev)) == 0) not true.
errno = 17 (File exists)
thread = (cache-epoll)
version = varnish-trunk revision eb8f35b
ident =
Linux,3.2.0-4-amd64,x86_64,-junix,-smalloc,-smalloc,-hclassic,epoll
Backtrace:
0x4334e4: pan_ic+0x134
0x4638ca: vwe_inject+0x9a
0x4635a1: Wait_Handle+0x171
0x463c57: vwe_thread+0x147
0x7f2018de6b50: libpthread.so.0(+0x6b50) [0x7f2018de6b50]
0x7f2018b3095d: libc.so.6(clone+0x6d) [0x7f2018b3095d]
}}}

'''OBS: I have attached the output of sysctl -a'''

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:21>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

I'm also running 6 instances of varnishncsa:

{{{
/usr/bin/varnishncsa -a -w /var/log/estadisticas/varnishncsa/XXXX.log -D
-P /var/run/XXXX.pid -F %h %{%s}t "%r" %s %b %{Varnish:hitmiss}x
"%{Referer}i" "%{User-agent}i" %{X-Domain}o %{X-Served-By}o -q ReqHeader ~
'Host: XXXX.com'
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:22>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by phk):

I just changed the whole backend/waiter thing around to avoid the race you
were hitting.

Can I persuade you to try -trunk once more ?

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:23>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs
Re: #1675: Condition((vbc->in_waiter) != 0) not true. [ In reply to ]
#1675: Condition((vbc->in_waiter) != 0) not true.
----------------------------------+----------------------------------
Reporter: zaterio@… | Owner: phk
Type: defect | Status: needinfo
Priority: normal | Milestone: Varnish 4.0 release
Component: varnishd | Version: trunk
Severity: normal | Resolution:
Keywords: in_waiter tcp_handle |
----------------------------------+----------------------------------

Comment (by zaterio@…):

just a update:

running 12ace86f88c18a1ec85b18578e6f36ae2d95d501, transferring 350 Mbits
for 2 hours (epoll waiter), no panics, 100% child uptime (previously we
had panics every 3 min with epoll).

{{{
varnishd -V
varnishd (varnish-trunk revision 12ace86)
Copyright (c) 2006 Verdens Gang AS
Copyright (c) 2006-2015 Varnish Software AS
}}}

--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1675#comment:24>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator

_______________________________________________
varnish-bugs mailing list
varnish-bugs@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-bugs

1 2  View All