Skip Menu |

This queue is for tickets about the Cache-Cache CPAN distribution.

Report information
The Basics
Id: 88418
Status: open
Priority: 0/
Queue: Cache-Cache

People
Owner: Nobody in particular
Requestors: zefram [...] fysh.org
Cc: gregoa [...] cpan.org
AdminCc:

Bug Information
Severity: (no value)
Broken in: (no value)
Fixed in: (no value)



Subject: intermittent size-aware test failure
Date: Wed, 4 Sep 2013 16:40:01 +0100
To: bug-Cache-Cache [...] rt.cpan.org
From: Zefram <zefram [...] fysh.org>
I'm intermittently seeing Cache-Cache fail its tests thus: t/5_test_size_aware_file_cache.t .... ok Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache-1.06-CTXYVU /blib/lib/Cache/CacheSizer.pm line 92. Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache-1.06-CTXYVU /blib/lib/Cache/CacheSizer.pm line 92. Use of uninitialized value $first_value in string eq at /opt/perl-5.18.1/cpan/bu ild/Cache-Cache-1.06-CTXYVU/blib/lib/Cache/SizeAwareCacheTester.pm line 149. t/6_test_size_aware_memory_cache.t .. Failed 1/48 subtests The test involves a series of cache entries that are ascribed sizes of 28 or 29. These sizes are being judged by Cache::MemoryCache::Backend::get_size(), which is looking at the length of the stringified form of an object, for which it gets strings such as "Cache::Object=HASH(0x17dfde8)"; the number of hexadecimal digits in the memory address accounts for the variability of the sizes. I conclude that the size estimation is entirely bogus. The test failure could be accounted for by a race condition in Cache::SizeAwareCacheTester::_test_two(). After setting a value for $first_key with expiry in 20 s, it sets values for five more keys, separated by sleep(1) calls, with expiry in 10 s. The test relies on $first_key having a later expiry time than any of the other five, so that the $cache->limit_size($size_limit) call evicts all keys other than $first_key. If there is an uncommanded pause amounting to 5 s during the process of setting the five keys, the last of them could have expiry time equal to or later than that of $first_key. If it's later then the test definitely fails; if it's tied then the result depends on hash order and relative perceived size of the cache entries. Adding a sleep(5) before the cache setting loop is enough to induce these failures. I haven't determined whether the above is how the intermittent failures that I've seen have occurred. There may be another failure mode. For my purposes, I'm disabling the size-aware cache tests, because (as noted above) the size awareness is bogus and we don't rely on it anyway. -zefram
From: ppisar [...] redhat.com
Dne St 04.zář.2013 11:40:19, zefram@fysh.org napsal(a): Show quoted text
> I'm intermittently seeing Cache-Cache fail its tests thus: > > t/5_test_size_aware_file_cache.t .... ok > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache- > 1.06-CTXYVU > /blib/lib/Cache/CacheSizer.pm line 92. > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache- > 1.06-CTXYVU > /blib/lib/Cache/CacheSizer.pm line 92. > Use of uninitialized value $first_value in string eq at /opt/perl- > 5.18.1/cpan/bu > ild/Cache-Cache-1.06-CTXYVU/blib/lib/Cache/SizeAwareCacheTester.pm > line 149. > t/6_test_size_aware_memory_cache.t .. > Failed 1/48 subtests >
[...] Show quoted text
> > The test failure could be accounted for by a race condition in > Cache::SizeAwareCacheTester::_test_two(). After setting a value for > $first_key with expiry in 20 s, it sets values for five more keys, > separated by sleep(1) calls, with expiry in 10 s. The test relies > on $first_key having a later expiry time than any of the other five, > so that the $cache->limit_size($size_limit) call evicts all keys other > than $first_key. If there is an uncommanded pause amounting to 5 s > during the process of setting the five keys, the last of them could > have > expiry time equal to or later than that of $first_key. If it's later > then the test definitely fails; if it's tied then the result depends > on > hash order and relative perceived size of the cache entries. Adding a > sleep(5) before the cache setting loop is enough to induce these > failures.
Attached patch should fix the time races in the tests. -- Petr
Subject: 0001-Make-tests-aware-of-running-time.patch
From 79b3decdb39c6a12261bb9a5f5bbada5ceec39eb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20P=C3=ADsa=C5=99?= <ppisar@redhat.com> Date: Thu, 26 Jun 2014 13:43:09 +0200 Subject: [PATCH] Make tests aware of running time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Some tests could fail if they run slower then the tested time limits because then caches entries expired on different place expected. This patch skips such tests if the running time is not shorter than expected. CPAN RT#88418 Signed-off-by: Petr Písař <ppisar@redhat.com> --- lib/Cache/CacheTester.pm | 30 ++++++++++++++++++++++++------ lib/Cache/SizeAwareCacheTester.pm | 10 ++++++++-- 2 files changed, 32 insertions(+), 8 deletions(-) diff --git a/lib/Cache/CacheTester.pm b/lib/Cache/CacheTester.pm index 8f64577..1cd6f82 100644 --- a/lib/Cache/CacheTester.pm +++ b/lib/Cache/CacheTester.pm @@ -168,12 +168,18 @@ sub _test_four my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -460,12 +466,18 @@ sub _test_thirteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -525,12 +537,18 @@ sub _test_fifteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); diff --git a/lib/Cache/SizeAwareCacheTester.pm b/lib/Cache/SizeAwareCacheTester.pm index 1a660f7..1a36c48 100644 --- a/lib/Cache/SizeAwareCacheTester.pm +++ b/lib/Cache/SizeAwareCacheTester.pm @@ -110,6 +110,7 @@ sub _test_two my $first_expires_in = 20; + my $start = time; $cache->set( $first_key, $value, $first_expires_in ); my $first_size = $cache->size( ); @@ -146,8 +147,13 @@ sub _test_two my $first_value = $cache->get( $first_key ); - ( $first_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + if (time - $start < $first_expires_in ) { + ( $first_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + } else { + $self->skip( '$first_value eq $value (not finished in ' . + $first_expires_in . ' s)'); + } } -- 1.9.3
From: ppisar [...] redhat.com
Dne Čt 26.čen.2014 08:48:21, ppisar napsal(a): Show quoted text
> Dne St 04.zář.2013 11:40:19, zefram@fysh.org napsal(a):
> > I'm intermittently seeing Cache-Cache fail its tests thus: > > > > t/5_test_size_aware_file_cache.t .... ok > > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache- > > 1.06-CTXYVU > > /blib/lib/Cache/CacheSizer.pm line 92. > > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache-Cache- > > 1.06-CTXYVU > > /blib/lib/Cache/CacheSizer.pm line 92. > > Use of uninitialized value $first_value in string eq at /opt/perl- > > 5.18.1/cpan/bu > > ild/Cache-Cache-1.06-CTXYVU/blib/lib/Cache/SizeAwareCacheTester.pm > > line 149. > > t/6_test_size_aware_memory_cache.t .. > > Failed 1/48 subtests > >
> [...]
> > > > The test failure could be accounted for by a race condition in > > Cache::SizeAwareCacheTester::_test_two(). After setting a value for > > $first_key with expiry in 20 s, it sets values for five more keys, > > separated by sleep(1) calls, with expiry in 10 s. The test relies > > on $first_key having a later expiry time than any of the other five, > > so that the $cache->limit_size($size_limit) call evicts all keys other > > than $first_key. If there is an uncommanded pause amounting to 5 s > > during the process of setting the five keys, the last of them could > > have > > expiry time equal to or later than that of $first_key. If it's later > > then the test definitely fails; if it's tied then the result depends > > on > > hash order and relative perceived size of the cache entries. Adding a > > sleep(5) before the cache setting loop is enough to induce these > > failures.
> > Attached patch should fix the time races in the tests. >
There was another race. Attached patch fixes it and replaces the previous patch. -- Petr
Subject: 0001-Make-tests-aware-of-running-time.patch
From 53b0e5405595a8a9b87b53dea1464584237f4dc7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20P=C3=ADsa=C5=99?= <ppisar@redhat.com> Date: Thu, 26 Jun 2014 13:43:09 +0200 Subject: [PATCH] Make tests aware of running time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Some tests could fail if they run slower then the tested time limits because then caches entries expired on different place than expected. This patch skips such tests if the running time is not shorter than expected. CPAN RT#88418 Signed-off-by: Petr Písař <ppisar@redhat.com> --- lib/Cache/CacheTester.pm | 30 ++++++++++++++++++++++++------ lib/Cache/SizeAwareCacheTester.pm | 19 +++++++++++++++---- 2 files changed, 39 insertions(+), 10 deletions(-) diff --git a/lib/Cache/CacheTester.pm b/lib/Cache/CacheTester.pm index 8f64577..1cd6f82 100644 --- a/lib/Cache/CacheTester.pm +++ b/lib/Cache/CacheTester.pm @@ -168,12 +168,18 @@ sub _test_four my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -460,12 +466,18 @@ sub _test_thirteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -525,12 +537,18 @@ sub _test_fifteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); diff --git a/lib/Cache/SizeAwareCacheTester.pm b/lib/Cache/SizeAwareCacheTester.pm index 1a660f7..1cf744f 100644 --- a/lib/Cache/SizeAwareCacheTester.pm +++ b/lib/Cache/SizeAwareCacheTester.pm @@ -110,6 +110,7 @@ sub _test_two my $first_expires_in = 20; + my $start = time; $cache->set( $first_key, $value, $first_expires_in ); my $first_size = $cache->size( ); @@ -132,8 +133,13 @@ sub _test_two my $second_size = $cache->size( ); - ( $second_size > $first_size ) ? - $self->ok( ) : $self->not_ok( '$second_size > $first_size' ); + if (time - $start < $first_expires_in ) { + ( $second_size > $first_size ) ? + $self->ok( ) : $self->not_ok( '$second_size > $first_size' ); + } else { + $self->skip( '$second_size > $first_size (not finished in ' . + $first_expires_in . ' s)'); + } my $size_limit = $first_size; @@ -146,8 +152,13 @@ sub _test_two my $first_value = $cache->get( $first_key ); - ( $first_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + if (time - $start < $first_expires_in ) { + ( $first_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + } else { + $self->skip( '$first_value eq $value (not finished in ' . + $first_expires_in . ' s)'); + } } -- 1.9.3
From: ppisar [...] redhat.com
Dne St 13.srp.2014 03:45:36, ppisar napsal(a): Show quoted text
> Dne Čt 26.čen.2014 08:48:21, ppisar napsal(a):
> > Dne St 04.zář.2013 11:40:19, zefram@fysh.org napsal(a):
> > > I'm intermittently seeing Cache-Cache fail its tests thus: > > > > > > t/5_test_size_aware_file_cache.t .... ok > > > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache- > > > Cache- > > > 1.06-CTXYVU > > > /blib/lib/Cache/CacheSizer.pm line 92. > > > Couldn't limit size to 28 at /opt/perl-5.18.1/cpan/build/Cache- > > > Cache- > > > 1.06-CTXYVU > > > /blib/lib/Cache/CacheSizer.pm line 92. > > > Use of uninitialized value $first_value in string eq at /opt/perl- > > > 5.18.1/cpan/bu > > > ild/Cache-Cache-1.06-CTXYVU/blib/lib/Cache/SizeAwareCacheTester.pm > > > line 149. > > > t/6_test_size_aware_memory_cache.t .. > > > Failed 1/48 subtests > > >
> > [...]
> > > > > > The test failure could be accounted for by a race condition in > > > Cache::SizeAwareCacheTester::_test_two(). After setting a value > > > for > > > $first_key with expiry in 20 s, it sets values for five more keys, > > > separated by sleep(1) calls, with expiry in 10 s. The test relies > > > on $first_key having a later expiry time than any of the other > > > five, > > > so that the $cache->limit_size($size_limit) call evicts all keys > > > other > > > than $first_key. If there is an uncommanded pause amounting to 5 s > > > during the process of setting the five keys, the last of them could > > > have > > > expiry time equal to or later than that of $first_key. If it's > > > later > > > then the test definitely fails; if it's tied then the result > > > depends > > > on > > > hash order and relative perceived size of the cache entries. > > > Adding a > > > sleep(5) before the cache setting loop is enough to induce these > > > failures.
> > > > Attached patch should fix the time races in the tests. > >
> There was another race. Attached patch fixes it and replaces the > previous patch. >
And this patch replacing the previous one fixes hopefully the last race betweem adding two key sets. Although there remains a small unexplained issue with limiting cache size warning described in <https://bugzilla.redhat.com/show_bug.cgi?id=1128792#c1>. -- Petr
Subject: 0001-Make-tests-aware-of-running-time.patch
From 847184c72a9e76612cd76e97b676af85202be27c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20P=C3=ADsa=C5=99?= <ppisar@redhat.com> Date: Thu, 26 Jun 2014 13:43:09 +0200 Subject: [PATCH] Make tests aware of running time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Some tests could fail if they run slower then the tested time limits because then caches entries expired on different place than expected. This patch skips such tests if the running time is not shorter than expected. CPAN RT#88418 Signed-off-by: Petr Písař <ppisar@redhat.com> --- lib/Cache/CacheTester.pm | 30 ++++++++++++++++++++++++------ lib/Cache/SizeAwareCacheTester.pm | 25 +++++++++++++++++++++---- 2 files changed, 45 insertions(+), 10 deletions(-) diff --git a/lib/Cache/CacheTester.pm b/lib/Cache/CacheTester.pm index 8f64577..1cd6f82 100644 --- a/lib/Cache/CacheTester.pm +++ b/lib/Cache/CacheTester.pm @@ -168,12 +168,18 @@ sub _test_four my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -460,12 +466,18 @@ sub _test_thirteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); @@ -525,12 +537,18 @@ sub _test_fifteen my $value = 'Test Value'; + my $start = time; $cache->set( $key, $value, $expires_in ); my $fetched_value = $cache->get( $key ); - ( $fetched_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + if (time - $start < $expires_in) { + ( $fetched_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$fetched_value eq $value' ); + } else { + $self->skip( '$fetched_value eq $value (not finished in ' . + $expires_in . ' s)' ); + } sleep( $EXPIRES_DELAY + 1 ); diff --git a/lib/Cache/SizeAwareCacheTester.pm b/lib/Cache/SizeAwareCacheTester.pm index 1a660f7..b2bcb79 100644 --- a/lib/Cache/SizeAwareCacheTester.pm +++ b/lib/Cache/SizeAwareCacheTester.pm @@ -110,6 +110,7 @@ sub _test_two my $first_expires_in = 20; + my $start = time; $cache->set( $first_key, $value, $first_expires_in ); my $first_size = $cache->size( ); @@ -129,11 +130,17 @@ sub _test_two $cache->set( $key, $value, $second_expires_in ); } + my $second_inserted = time; my $second_size = $cache->size( ); - ( $second_size > $first_size ) ? - $self->ok( ) : $self->not_ok( '$second_size > $first_size' ); + if (time - $start < $first_expires_in ) { + ( $second_size > $first_size ) ? + $self->ok( ) : $self->not_ok( '$second_size > $first_size' ); + } else { + $self->skip( '$second_size > $first_size (not finished in ' . + $first_expires_in . ' s)'); + } my $size_limit = $first_size; @@ -146,8 +153,18 @@ sub _test_two my $first_value = $cache->get( $first_key ); - ( $first_value eq $value ) ? - $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + if (time - $start >= $first_expires_in) { + $self->skip( '$first_value eq $value (not finished in ' . + $first_expires_in . ' s)'); + } elsif ($second_inserted + $second_expires_in >= + $start + $first_expires_in) { + $self->skip( '$first_value eq $value (second key insterted to late, ' . + 'so first key had expiration time before the second one, ' . + 'thus the first key was removed when limit cache size'); + } else { + ( $first_value eq $value ) ? + $self->ok( ) : $self->not_ok( '$first_value eq $value' ); + } } -- 1.9.3
Looks like Petr's patch is not enough, unfortunately. Cf. https://bugs.debian.org/766102 and (linked from there) http://ci.debian.net/data/packages/unstable/amd64/libc/libcache-cache-perl/20141101_214223.autopkgtest.log Cheers, gregor
I have applied this patches, though they may not be sufficient. -- rjbs