Seeing failed assertion iterator errors with file driver, v. 0.34
Barry Hoggard
my $max_cache_size = 100 * 1024 * 1024;
$cache = CHI->new(
namespace => $namespace,
driver => "File",
root_dir => $cache_dir,
label => $namespace,
serializer => "Storable",
max_size => $max_cache_size,
expires_variance => $expires_variance
);
Under any significant load, we are seeing this in the logs:
Assertion (iterator returned undef, cache should be empty) failed!\n
at /local/home/raws/raws/lib/Carp/Assert.pm line
340\n\tCarp::Assert::affirm('CODE(0x9e728c4)', 'iterator returned
undef, cache should be empty') called at
/local/home/raws/raws/lib/CHI/Driver/Role/IsSizeAware.pm line
132\n\teval {...} called at
/local/home/raws/raws/lib/CHI/Driver/Role/IsSizeAware.pm line
121\n\tClass::MOP::Class::__ANON__::SERIAL::1::discard_to_size('Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
40000) called at
/local/home/raws/raws/lib/CHI/Driver/Role/IsSizeAware.pm line
74\n\tClass::MOP::Class:::around('CODE(0x9595414)',
'Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
'91d403cfb2d7d02a8a5fe4f5ba5e6fa2',
'CHI::CacheObject=ARRAY(0xa312114)') called at
/local/home/raws/raws/lib/i386-linux-thread-multi/Class/MOP/Method/Wrapped.pm
line 139\n\tClass::MOP::Method::Wrapped::__ANON__('Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
'91d403cfb2d7d02a8a5fe4f5ba5e6fa2',
'CHI::CacheObject=ARRAY(0xa312114)') called at
/local/home/raws/raws/lib/i386-linux-thread-multi/Class/MOP/Method/Wrapped.pm
line 89\n\tClass::MOP::Class::__ANON__::SERIAL::1::set_object('Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
'91d403cfb2d7d02a8a5fe4f5ba5e6fa2',
'CHI::CacheObject=ARRAY(0xa312114)') called at
/local/home/raws/raws/lib/CHI/Driver.pm line
311\n\tCHI::Driver::set_with_options('Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
'91d403cfb2d7d02a8a5fe4f5ba5e6fa2', 'ARRAY(0x9e77028)',
'HASH(0x9e76110)') called at /local/home/raws/raws/lib/CHI/Driver.pm
line 282\n\tCHI::Driver::set('Class::MOP::Class::__ANON__::SERIAL::1=HASH(0x9637c70)',
'91d403cfb2d7d02a8a5fe4f5ba5e6fa2', 'ARRAY(0x9e77028)', 'now')
Does this problem look familiar? Any advice on how to debug it?
Under normal unit tests we never get this error.
--
Barry Hoggard
www.tristanmedia.com
aim: hoggardb
p: 347-455-1966
skype: bhoggard
Barry Hoggard
$ perl -V
Summary of my perl5 (revision 5 version 8 subversion 8) configuration:
Platform:
osname=linux, osvers=2.6.18-128.1.10.el5, archname=i386-linux-
thread-multi
uname='linux ls20-bc1-14.build.redhat.com 2.6.18-128.1.10.el5 #1
smp wed apr 29 13:53:08 edt 2009 i686 athlon i386 gnulinux '
config_args='-des -Doptimize=-O2 -g -pipe -Wall -Wp,-
D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-
size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -
Dversion=5.8.8 -Dmyhostname=localhost -Dperladmin=root@localhost -
Dcc=gcc -Dcf_by=Red Hat, Inc. -Dinstallprefix=/usr -Dprefix=/usr -
Darchname=i386-linux-thread-multi -Dvendorprefix=/usr -Dsiteprefix=/
usr -Duseshrplib -Dusethreads -Duseithreads -Duselargefiles -Dd_dosuid
-Dd_semctl_semun -Di_db -Ui_ndbm -Di_gdbm -Di_shadow -Di_syslog -
Dman3ext=3pm -Duseperlio -Dinstallusrbinperl=n -Ubincompat5005 -
Uversiononly -Dpager=/usr/bin/less -isr -Dd_gethostent_r_proto -
Ud_endhostent_r_proto -Ud_sethostent_r_proto -Ud_endprotoent_r_proto -
Ud_setprotoent_r_proto -Ud_endservent_r_proto -Ud_setservent_r_proto -
Dinc_version_list=5.8.7 5.8.6 5.8.5 -Dscriptdir=/usr/bin'
hint=recommended, useposix=true, d_sigaction=define
usethreads=define use5005threads=undef useithreads=define
usemultiplicity=define
useperlio=define d_sfio=undef uselargefiles=define usesocks=undef
use64bitint=undef use64bitall=undef uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
cc='gcc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -fno-strict-
aliasing -pipe -Wdeclaration-after-statement -I/usr/local/include -
D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -I/usr/include/gdbm',
optimize='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -
fstack-protector --param=ssp-buffer-size=4 -m32 -march=i386 -
mtune=generic -fasynchronous-unwind-tables',
cppflags='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -
Wdeclaration-after-statement -I/usr/local/include -I/usr/include/gdbm'
ccversion='', gccversion='4.1.2 20080704 (Red Hat 4.1.2-44)',
gccosandvers=''
intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
d_longlong=define, longlongsize=8, d_longdbl=define,
longdblsize=12
ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t',
lseeksize=8
alignbytes=4, prototype=define
Linker and Libraries:
ld='gcc', ldflags =' -L/usr/local/lib'
libpth=/usr/local/lib /lib /usr/lib
libs=-lresolv -lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -
lc
perllibs=-lresolv -lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
libc=/lib/libc-2.5.so, so=so, useshrplib=true, libperl=libperl.so
gnulibc_version='2.5'
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E -
Wl,-rpath,/usr/lib/perl5/5.8.8/i386-linux-thread-multi/CORE'
cccdlflags='-fPIC', lddlflags='-shared -O2 -g -pipe -Wall -Wp,-
D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-
size=4 -m32 -march=i386 -mtune=generic -fasynchronous-unwind-tables -L/
usr/local/lib'
Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_IMPLICIT_CONTEXT
PERL_MALLOC_WRAP USE_ITHREADS USE_LARGE_FILES
USE_PERLIO USE_REENTRANT_API
Built under linux
Compiled at Jul 2 2009 05:48:59
@INC:
/usr/lib/perl5/site_perl/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/site_perl/5.8.8
/usr/lib/perl5/site_perl
/usr/lib/perl5/vendor_perl/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.8.8
/usr/lib/perl5/vendor_perl
/usr/lib/perl5/5.8.8/i386-linux-thread-multi
/usr/lib/perl5/5.8.8
.
Jonathan Swartz
I wouldn't use max_size with the File driver, for two reasons. First,
the size cannot be kept 100% accurately because of race conditions,
and I expect this is the cause of the assert error. As it says in the
docs,
for drivers that cannot atomically read and update a
value - for example, CHI::Driver::File - there is a race
condition in the updating of size that can cause the size to
grow inaccurate over time.
Second, each set will result in an extra set for the size, thus
doubling the cost of writes.
It is easy enough to write a purge script that deletes all cache files
older than a certain time:
# Remove cache files older than 4 hours
find . -type f -name "*.dat" -mmin +240 | xargs rm -f
That isn't as good as enforcing a maximum size, but you can adjust the
time to get the same effect.
Alternately, use FastMmap or Memcached, which inherently keep track of
their size and enforce a maximum size.
I'll make the above docs language a little stronger in this regard.
Hope that helps,
Jon