Valgrind: invalid reads & writes by compaction thread

[slfritchie]

All of these messages appear to come from a single test case. I'll try to figure out if this is deterministic or not -- I haven't created a clever way to have QuickCheck recognize when valgrind spots an error. I have a manual way to do it, but it's manual and requires a huge amount of babysitting and is only worthwhile on 100% deterministic cases.

==5359== Thread 121:
==5359== Invalid read of size 4
==5359==    at 0x134778A5: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:106)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b3c is 60 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x134778C1: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:46)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b18 is 24 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x134778C7: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:49)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b30 is 48 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 1
==5359==    at 0x4C2DCAE: bcmp (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x134778DC: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (slice.h:89)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b48 is 72 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 1
==5359==    at 0x4C2DCC6: bcmp (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x134778DC: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (slice.h:89)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b49 is 73 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x134778E6: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:88)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b10 is 16 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x13476D80: leveldb::LRUCache2::LRU_Remove(leveldb::LRUHandle2*) (cache2.cc:238)
==5359==    by 0x134778FC: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:271)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b18 is 24 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x13476D84: leveldb::LRUCache2::LRU_Remove(leveldb::LRUHandle2*) (cache2.cc:238)
==5359==    by 0x134778FC: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:271)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b20 is 32 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 8
==5359==    at 0x13476D8C: leveldb::LRUCache2::LRU_Remove(leveldb::LRUHandle2*) (cache2.cc:239)
==5359==    by 0x134778FC: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:271)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b20 is 32 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid read of size 4
==5359==    at 0x13477448: leveldb::LRUCache2::Unref(leveldb::LRUHandle2*) (cache2.cc:621)
==5359==    by 0x13477907: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:272)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b38 is 56 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 
==5359== Invalid write of size 4
==5359==    at 0x13477450: leveldb::LRUCache2::Unref(leveldb::LRUHandle2*) (cache2.cc:621)
==5359==    by 0x13477907: leveldb::LRUCache2::Erase(leveldb::Slice const&, unsigned int) (cache2.cc:272)
==5359==    by 0x13463F0A: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:166)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359==  Address 0x7fb03b38 is 56 bytes inside a block of size 87 free'd
==5359==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==5359==    by 0x1347796F: leveldb::LRUCache2::Release(leveldb::Cache::Handle*) (cache2.cc:254)
==5359==    by 0x13463F6E: leveldb::TableCache::Evict(unsigned long, bool) (table_cache.cc:162)
==5359==    by 0x134555EF: leveldb::DBImpl::DoCompactionWork(leveldb::DBImpl::CompactionState*) (db_impl.cc:1433)
==5359==    by 0x1345582C: leveldb::DBImpl::BackgroundCompaction(leveldb::Compaction*) (db_impl.cc:1032)
==5359==    by 0x13456815: leveldb::DBImpl::BackgroundCall2(leveldb::Compaction*) (db_impl.cc:889)
==5359==    by 0x1345A7D0: leveldb::CompactionTask::operator()() (thread_tasks.h:124)
==5359==    by 0x1347EB7A: leveldb::HotThread::ThreadRoutine() (hot_threads.cc:102)
==5359==    by 0x5767E99: start_thread (pthread_create.c:308)
==5359== 

[slfritchie]

Oops, how about a couple more details?

eleveldb: commit 639f69c and then the patches on the slf-faulterl-introduction2 branch
leveldb: commit 6728f90cd7cc0afb5a1e4e839861bfac03dd1fe3 on the mv-imm-retry branch.

Not easily repeatable, sorry!

[matthewvon]

This appears to be an error when shutting down the database that has an active compaction. Does that sound correct?

If so, would you attempt your test again with lines 1426 through 1435 of db/db_impl.cc commented out. Those lines were added due to valgrind testing a long time ago (like a year ago). Something may have changed.

[slfritchie]

This appears to be an error when shutting down the database that has an active compaction.

Quite likely. The valgrind errors happened while running the following test case 20 times in a row: https://gist.github.com/slfritchie/1d2900a7a53e53ef2e82 ... all 20 passed, and only 1 of the 20 runs managed to trigger any Valgrind complaints.

There are 8 open() & 7 close() calls in that test case. The faulterl C code is calling srand(3) at the beginning of each test run, but I only tiny amounts of clue about how the Debian Linux wheezy/sid version of glibc deals with multi-threaded calls to srand(3) and rand(3).

[slfritchie]

While trying to reproduce this error according to Matthew's advice from 10 hours ago (about lines 1426-1435), I re-ran with the faulterl library LD_PRELOAD'ed but with the main fault injection configuration option disabling all fault injection. I managed to hit the same invalid reads & writes on the first try. So, fault injection appears not to be 100% necessary to hit this problem, yay.

Cut-and-paste the contents of the gist above into an Erlang shell to bind the variable Ch. Then run the test case using this command to run with fault injection disabled:

[true = eqc:check(eqc:testing_time(3*60, generic_qc_fsm:prop(false, false)), Ch) || _ <- lists:seq(1,100)].

[matthewvon]

How did valgrind change with the lines removed?

[slfritchie]

Today's status:

• The paranoid_checks value is eleveldb's default
• Eleveldb commit: 2a72ad3
  • Which is based off of today's develop branch at commit 9ab8ed6
• Leveldb commit: f4cf10d2ba1b999f10805ac35f22145e80932544 (today's develop)
  • Plus the diff below

It looks like the develop branch of the leveldb repo has moved recently? So your line numbers are off. I took my best guess and applied this patch:

diff --git a/db/db_impl.cc b/db/db_impl.cc
index d30e60a..be4d74b 100644
--- a/db/db_impl.cc
+++ b/db/db_impl.cc
@@ -1432,13 +1432,13 @@ Status DBImpl::DoCompactionWork(CompactionState* compact

     // cleanup Riak modification that adds extra reference
     //  to overlap levels files.
-    if (compact->compaction->level() < config::kNumOverlapLevels)
-    {
-        for (size_t i = 0; i < compact->outputs.size(); i++) {
-            const CompactionState::Output& out = compact->outputs[i];
-            versions_->GetTableCache()->Evict(out.number, true);
-        }   // for
-    }   // if
+//per-MvM:    if (compact->compaction->level() < config::kNumOverlapLevels)
+//per-MvM:    {
+//per-MvM:        for (size_t i = 0; i < compact->outputs.size(); i++) {
+//per-MvM:            const CompactionState::Output& out = compact->outputs[i];
+//per-MvM:            versions_->GetTableCache()->Evict(out.number, true);
+//per-MvM:        }   // for
+//per-MvM:    }   // if
   }
   if (status.ok() && compact->builder != NULL) {
     status = FinishCompactionOutputFile(compact, input);

And I saw this Valgrind complaint:

==2268== Thread 75:
==2268== Invalid write of size 8
==2268==    at 0x1344A840: eleveldb::RefObject::~RefObject() (refobjects.cc:51)
==2268==    by 0x1344AA58: eleveldb::DbObject::~DbObject() (refobjects.cc:290)
==2268==    by 0x1344A933: eleveldb::ErlRefObject::RefDec() (refobjects.cc:181)
==2268==    by 0x1344A5FC: eleveldb::LevelIteratorWrapper::~LevelIteratorWrapper() (refobjects.h:146)
==2268==    by 0x1344A95D: eleveldb::RefObject::RefDec() (refobjects.cc:73)
==2268==    by 0x1344D7A5: eleveldb::MoveTask::~MoveTask() (refobjects.h:146)
==2268==    by 0x1344A95D: eleveldb::RefObject::RefDec() (refobjects.cc:73)
==2268==    by 0x1344BA51: eleveldb::eleveldb_write_thread_worker(void*) (threading.cc:382)
==2268==    by 0x549338: erl_drv_thread_wrapper (erl_drv_thread.c:117)
==2268==    by 0x612A14: thr_wrapper (ethread.c:106)
==2268==    by 0x5767E99: start_thread (pthread_create.c:308)
==2268==  Address 0x633c568 is 40 bytes inside a block of size 216 free'd
==2268==    at 0x4C2A82E: free (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==2268==    by 0x5A624A: erts_sys_free (sys.c:2553)
==2268==    by 0x52607F: erts_free (erl_alloc.h:239)
==2268==    by 0x526AB7: erts_bin_free (erl_binary.h:307)
==2268==    by 0x52C7A0: sweep_off_heap (erl_gc.c:2309)
==2268==    by 0x52A7D5: major_collection (erl_gc.c:1384)
==2268==    by 0x527486: erts_garbage_collect (erl_gc.c:437)
==2268==    by 0x5831FF: new_fun (beam_emu.c:6186)
==2268==    by 0x57EF8A: process_main (beam_cold.h:200)
==2268==    by 0x4B6244: sched_thread_func (erl_process.c:5801)
==2268==    by 0x612A14: thr_wrapper (ethread.c:106)
==2268==    by 0x5767E99: start_thread (pthread_create.c:308)
==2268== 

[matthewvon]

The first valgrind report was a nuisance issue. This second one is bad. The second one suggests the database actually closed before an iterator completed.

I can think of two scenarios:

1. your test intentionally closes the db before releasing the iterator … one code path.
2. your test closed the iterator first, but there is a prefetch running in the background … second code path. In this case, something did not honor the reference count while closing the database.

Do you know if your test intentionally creates scenario one? Independently, need to watch to see if the original valgrind report ever occurs again.

[matthewvon]

There is now an eleveldb/mv-tuning7 branch (parallel to leveldb mv-tuning7) that addresses the likely scenario producing the second Valgrind report. This is by no means a comprehensive fix to the imagined "API calls after db close" scenario. It is more of a proof of concept / understanding.

[slfritchie]

I can think of two scenarios:

1. your test intentionally closes the db before releasing the iterator … one code path.

Not without an error in the Erlang compiler or VM that fails to execute code in the after block at https://github.com/basho/eleveldb/blob/slf-faulterl-introduction2/src/eleveldb.erl#L329-L339

1. your test closed the iterator first, but there is a prefetch running in the background … second code path.

That's a bit interesting. Lines 329-339 show that the fold is always running to completion/exception throwing before returning control to the QuickCheck test code. It seems like the signal from leveldb that the iterator has found the right edge of the keyspace by some_iterator->Valid() returning false. The eleveldb wrapper appears to turn that into {error, invalid_iterator}, which the Erlang fold_loop() code uses to stop calling iterator_move(). Is it possible for prefetch to keep trying to do something after some_iterator->Valid() really returns false?

[matthewvon]

Theory of the moment is that I interpreted the second Valgrind stack incorrectly. My new interpretation is that "Invalid write of size 8" at refobjects.cc:51 is really an attempt to update the performance counters. The performance counter code is expected (by me) to create a shared memory map and never unmap it. Maybe something unmaps it implicitly in the test cycle? Continuing to research this interpretation for now.

[slfritchie]

New symptom, discussed this afternoon with @matthewvon:

=5189== Warning: set address range perms: large range [0x1088d5040, 0x11e7b16b0) (undefined)
==5189== Warning: set address range perms: large range [0xf29f8030, 0x1088d46c0) (noaccess)
==5189== Warning: set address range perms: large range [0x1088d5030, 0x11e7b16c0) (noaccess)