disable auto compaction about goleveldb HOT 12 CLOSED

Compaction is important in leveldb, without compaction deleted keys will never get deleted. Could you please post the panic?

from goleveldb.

I either get a panic or corruption.

Here is the latest one:

from goleveldb.

Thanks. Could you also post the panic message?

from goleveldb.

No panic. but btcdb (the pkg using goleveldb) complains and just starts spewing out "Adding orphan block".

Other times I see from key.go this hit, where p is empty, len(p) is 0.
panic(fmt.Sprintf("invalid iKey %q, len=%d", []byte(p), len(p)))

I'll paste the trace if I hit that again.

from goleveldb.

It looks like a corruption in the sstable.

There is been some changes recently, where slice returned by DB.Get, Snapshot.Get and iterator key/value getter are not copied anymore when returned.
It is possible that the returned slice was altered in some way which led to the corruption.
Also, if you use an iterator, the slice returned by the key/value getter will only valid until next call to 'seeks method'.

EDIT: I mean sstable not memdb.

from goleveldb.

btcdb contains 4 DB.Gets, each followed by a bytes.NewBuffer() or copy(). Snapshot or iterators are not used. So I am not sure yet. I'll see if I can get something new.

Another user reported btcsuite/btcd#18

from goleveldb.

Ok then, could you please set opt.OFStrict flag, so that corruption could possibly catch early.

And for btcsuite/btcd#18, I think I found the cause of the issue. Hang on.

from goleveldb.

ok, this is without OFStrict since it was already running. I will start it again with OFStrict.

01:30:09 2013-10-14 [INF] BTCD: BMGR: Processed 52 blocks in the last 10.33s (1747 transactions, height 146423, 2011-09-22 06:38:33 -0400 EDT)
01:30:20 2013-10-14 [INF] BTCD: BMGR: Processed 41 blocks in the last 10.11s (1665 transactions, height 146464, 2011-09-22 13:23:12 -0400 EDT)
01:30:30 2013-10-14 [INF] BTCD: BMGR: Processed 34 blocks in the last 10.04s (1630 transactions, height 146498, 2011-09-22 18:34:59 -0400 EDT)
panic: runtime error: slice bounds out of range [recovered]
        panic: runtime error: slice bounds out of range [recovered]
        panic: runtime error: slice bounds out of range
goroutine 8 [running]:
runtime.panic(0x9d9740, 0x10fdb2a)
        /home/dhill/git/go/src/pkg/runtime/panic.c:266 +0xb6
github.com/conformal/goleveldb/leveldb.func·018()
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:430 +0xea
runtime.panic(0x9d9740, 0x10fdb2a)
        /home/dhill/git/go/src/pkg/runtime/panic.c:248 +0x106
github.com/conformal/goleveldb/leveldb.func·008()
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:147 +0x20f
runtime.panic(0x9d9740, 0x10fdb2a)
        /home/dhill/git/go/src/pkg/runtime/panic.c:248 +0x106
github.com/conformal/goleveldb/leveldb/table.(*blockIter).Next(0xc210dafb40, 0x2a)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/table/reader.go:219 +0x3df
github.com/conformal/goleveldb/leveldb/iterator.(*indexedIterator).Next(0xc2120bc460, 0x33d)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/iterator/indexed_iter.go:119 +0x4c
github.com/conformal/goleveldb/leveldb/iterator.(*indexedIterator).Next(0xc211a01c80, 0x2038ddd30)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/iterator/indexed_iter.go:119 +0x4c
github.com/conformal/goleveldb/leveldb/iterator.(*mergedIterator).Next(0xc211dd9980, 0xc2114c1270)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/iterator/merged_iter.go:177 +0x2cd
github.com/conformal/goleveldb/leveldb.func·015(0x0, 0x0)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:278 +0x3bd
github.com/conformal/goleveldb/leveldb.(*DB).transact(0xc21004a6c0, 0xaaa6f0, 0xb, 0x2013b2dd8, 0x2013b2bf8)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:155 +0x1ca
github.com/conformal/goleveldb/leveldb.(*DB).doCompaction(0xc21004a6c0, 0xc2134798c0, 0x2013b2f00)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:407 +0xacf
github.com/conformal/goleveldb/leveldb.(*DB).compaction(0xc21004a6c0)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:472 +0x1c6
created by github.com/conformal/goleveldb/leveldb.openDB
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db.go:117 +0x443

Here is LOG. memflush at 1:30:30 .. same time as panic started.

01:30:28.783139 table@compaction created L3@11819 N·9791 S·1MiB "1..8,v3949575":"1..x,v2286375"
01:30:28.822542 table@compaction commited F~ S-6B D·0 T·576.963276ms
01:30:28.881426 table@compaction L1·1 -> L2·10 S·20MiB Q·3973392
01:30:30.087696 table@compaction created L2@11820 N·35177 S·2MiB "n..x,v3571076":"s..x,v3746099"
01:30:30.261655 mem@flush N·18846 S·4MiB
01:30:30.568920 mem@flush created L0@11823 N·18846 S·3MiB "\x00..x,v3970292":"\xff..x,v3956083"
01:30:30.581657 mem@flush commited F·1 T·319.895129ms
01:30:31.010468 table@compaction created L2@11821 N·35157 S·2MiB "s..x,v1416898":"y..x,v434220"
01:30:31.436752 table@compaction created L2@11824 N·35137 S·2MiB "y..x,v3931081":"~..\x00,v3025993"
01:30:31.752324 table@compaction created L2@11825 N·35144 S·2MiB "~..x,v2937561":"\x83..x,v3658042"
01:30:32.070163 table@compaction created L2@11826 N·35162 S·2MiB "\x83..x,v928758":"\x89..x,v1294310"
01:30:32.365280 table@compaction created L2@11827 N·35127 S·2MiB "\x89..x,v3273718":"\x8e..x,v3035584"
01:30:32.727671 table@compaction created L2@11828 N·35145 S·2MiB "\x8e..x,v743347":"\x93..x,v2729236"
01:30:33.069207 table@compaction created L2@11829 N·35161 S·2MiB "\x93..x,v1727837":"\x98..\x00,v113363"
01:30:33.446594 table@compaction created L2@11830 N·35211 S·2MiB "\x98..x,v248833":"\x9e..\x00,v31240"
01:30:33.911777 table@compaction created L2@11831 N·35145 S·2MiB "\x9e..x,v1656815":"\xa3..x,v3752822"
01:30:33.952755 table@compaction created L2@11832 N·1372 S·80KiB "\xa3..x,v1937837":"\xa3..x,v1713333"
01:30:33.972971 table@compaction commited F~ S-93KiB D·1481 T·4.76414771s
01:30:34.040304 table@compaction L0·1 -> L1·1 S·4MiB Q·3974193
01:30:34.286017 table@compaction created L1@11833 N·2446 S·2MiB "\x00..x,v3970292":"1..3,v3966871"
01:30:34.503667 table@compaction created L1@11834 N·429 S·1MiB "1..4,v3967000":"9..x,v3970160"
01:30:34.639577 table@compaction created L1@11835 N·2320 S·141KiB "9..x,v3972385":"h..x,v3958732"
01:30:34.761631 table@compaction created L1@11836 N·2488 S·152KiB "h..x,v3962580":"\x9e..x,v3970291"
01:30:34.923301 table@compaction created L1@11837 N·2487 S·152KiB "\x9e..x,v3973454":"\xd3..x,v3956145"
01:30:35.054785 table@compaction created L1@11838 N·3598 S·219KiB "\xd3..x,v3964713":"\xff..x,v3954046"
01:30:35.063736 table@compaction commited F+4 S-220KiB D·6889 T·1.023339006s
01:30:35.598996 table@compaction L1·1 -> L2·1 S·2MiB Q·3974961
01:30:35.661052 table@compaction created L2@11839 N·2332 S·142KiB "\x00..x,v3970292":"1..x,v3969085"
01:30:35.666774 table@compaction created L2@11840 N·1 S·163B "1..x,v3968150":"1..x,v3968150"
01:30:35.670819 table@compaction created L2@11841 N·2 S·225B "1..x,v3972053":"1..x,v3970000"
01:30:35.877961 table@compaction created L2@11842 N·97 S·2MiB "1..6,v3951126":"1..2,v3964257"
01:30:35.966041 table@compaction created L2@11843 N·1088 S·511KiB "1..3,v3964409":"6..x,v3924131"
01:30:35.974004 table@compaction commited F+3 S+236B D·0 T·374.918603ms
01:30:35.974352 table@compaction L2·1 -> L3·1 S·4MiB Q·3975345
01:30:36.217586 table@compaction created L3@11844 N·94 S·2MiB "1..8,v3949575":"1..2,v3962665"
01:30:36.482273 table@compaction created L3@11845 N·9794 S·1MiB "1..3,v3962916":"1..x,v2286375"
01:30:36.497387 table@compaction commited F~ S-31B D·0 T·522.952501ms
01:30:36.497827 table@compaction L1·1 -> L2·10 S·17MiB Q·3975605
01:30:36.939115 table@compaction created L2@11846 N·35145 S·2MiB "\xd3..x,v955681":"\xd8..x,v3150056"
01:30:37.933938 table@compaction created L2@11847 N·35137 S·2MiB "\xd8..x,v1580998":"\xde..x,v3719344"
01:30:38.865840 table@compaction created L2@11848 N·35148 S·2MiB "\xde..x,v3078612":"\xe3..x,v1304233"

from goleveldb.

Another

11:13:18 2013-10-14 [INF] BTCD: BMGR: Processed 51 blocks in the last 10.11s (2848 transactions, height 144405, 2011-09-07 18:18:46 -0400 EDT)
11:13:28 2013-10-14 [INF] BTCD: BMGR: Processed 39 blocks in the last 10.02s (2107 transactions, height 144444, 2011-09-08 02:28:45 -0400 EDT)
panic: invalid iKey "", len=0 [recovered]
        panic: invalid iKey "", len=0 [recovered]
        panic: invalid iKey "", len=0
goroutine 8 [running]:
runtime.panic(0x913ea0, 0xc21261e4a0)
        /home/dhill/git/go/src/pkg/runtime/panic.c:266 +0xb6
github.com/conformal/goleveldb/leveldb.func·018()
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:430 +0xea
runtime.panic(0x913ea0, 0xc21261e4a0)
        /home/dhill/git/go/src/pkg/runtime/panic.c:248 +0x106
github.com/conformal/goleveldb/leveldb.func·008()
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:147 +0x20f
runtime.panic(0x913ea0, 0xc21261e4a0)
        /home/dhill/git/go/src/pkg/runtime/panic.c:248 +0x106
github.com/conformal/goleveldb/leveldb.iKey.assert(0xc210d04780, 0x0, 0x2a)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/key.go:88 +0x189
github.com/conformal/goleveldb/leveldb.iKey.ukey(0xc210d04780, 0x0, 0x2a, 0xc212dad150, 0x22, ...)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/key.go:93 +0x3b                                                                          
github.com/conformal/goleveldb/leveldb.(*iComparer).Compare(0xc210044ae0, 0xc212dad150, 0x2a, 0x2a, 0xc210d04780, ...)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/comparer.go:21 +0xd0
github.com/conformal/goleveldb/leveldb/iterator.(*mergedIterator).next(0xc2122c7c80, 0xc210d04780)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/iterator/merged_iter.go:142 +0x111
github.com/conformal/goleveldb/leveldb/iterator.(*mergedIterator).Next(0xc2122c7c80, 0xc210d04780)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/iterator/merged_iter.go:192 +0x389
github.com/conformal/goleveldb/leveldb.func·015(0x0, 0x0)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:278 +0x3bd
github.com/conformal/goleveldb/leveldb.(*DB).transact(0xc2100546c0, 0xaab070, 0xb, 0x20917cdd8, 0x20917cbf8)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:155 +0x1ca
github.com/conformal/goleveldb/leveldb.(*DB).doCompaction(0xc2100546c0, 0xc212e0b620, 0x20917cf00)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:407 +0xacf
github.com/conformal/goleveldb/leveldb.(*DB).compaction(0xc2100546c0)
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db_compaction.go:472 +0x1c6
created by github.com/conformal/goleveldb/leveldb.openDB
        /home/dhill/.go/src/github.com/conformal/goleveldb/leveldb/db.go:117 +0x443

LOG

11:13:05.839064 table@compaction L1·1 -> L2·11 S·20MiB Q·3691383
11:13:06.270363 table@compaction created L2@6767 N·35164 S·2MiB "c..x,v1586030":"h..x,v2613619"
11:13:06.941930 table@compaction created L2@6768 N·35175 S·2MiB "h..x,v1410691":"n..x,v3205026"
11:13:07.644246 table@compaction created L2@6769 N·35193 S·2MiB "n..x,v516161":"t..x,v1659477"
11:13:08.458061 table@compaction created L2@6770 N·35167 S·2MiB "t..x,v3114827":"y..x,v864938"
11:13:09.234836 table@compaction created L2@6771 N·35155 S·2MiB "y..x,v55660":"\u007f..x,v2897802"
11:13:09.702356 table@compaction created L2@6772 N·35162 S·2MiB "\u007f..x,v3405015":"\x85..x,v2781760"
11:13:10.029889 table@compaction created L2@6773 N·35156 S·2MiB "\x85..x,v486238":"\x8a..x,v2648577"
11:13:10.679187 table@compaction created L2@6774 N·35167 S·2MiB "\x8a..x,v522772":"\x90..x,v3336955"
11:13:11.284851 table@compaction created L2@6775 N·35166 S·2MiB "\x90..\x00,v661768":"\x96..x,v3306087"
11:13:11.891642 table@compaction created L2@6776 N·35192 S·2MiB "\x96..x,v1647813":"\x9b..x,v2109612"
11:13:12.069120 table@compaction created L2@6777 N·6363 S·372KiB "\x9b..\x00,v545353":"\x9c..x,v1622915"
11:13:12.112102 table@compaction commited F-1 S-81KiB D·1261 T·6.272942758s
11:13:16.025903 mem@flush N·18471 S·4MiB
11:13:16.295671 mem@flush created L0@6779 N·18471 S·3MiB "\x00..x,v3695406":"\xff..x,v3687467"
11:13:16.306281 mem@flush commited F·1 T·280.297776ms
11:13:16.620357 table@compaction L0·1 -> L1·0 S·3MiB Q·3698118
11:13:16.705212 table@compaction created L1@6780 N·2296 S·140KiB "\x00..x,v3695406":"0..x,v3692079"
11:13:16.850767 table@compaction created L1@6781 N·101 S·2MiB "0..2,v3679106":"0..2,v3691681"
11:13:17.063226 table@compaction created L1@6782 N·2800 S·1MiB "0..3,v3691937":"h..x,v3679818"
11:13:17.131899 table@compaction created L1@6783 N·2738 S·168KiB "h..x,v3693822":"\xa2..x,v3691644"
11:13:17.195463 table@compaction created L1@6784 N·2861 S·175KiB "\xa2..x,v3685456":"\xdc..x,v3679438"
11:13:17.273983 table@compaction created L1@6785 N·1788 S·109KiB "\xdc..x,v3688112":"\xff..x,v3688109"
11:13:17.280203 table@compaction commited F+5 S-182KiB D·5887 T·659.736595ms
11:13:17.588672 table@compaction expanding L1+L2 (F·1 S·1MiB)+(F·11 S·21MiB) -> (F·2 S·3MiB)+(F·11 S·21MiB)
11:13:17.588890 table@compaction L1·2 -> L2·11 S·24MiB Q·3698893
11:13:17.814403 table@compaction created L2@6786 N·100 S·2MiB "0..3,v3673613":"0..2,v3686141"
11:13:18.095253 table@compaction created L2@6787 N·3333 S·2MiB "0..3,v3686344":"0..x,v2159142"
11:13:18.667655 table@compaction created L2@6788 N·35189 S·2MiB "0..x,v623976":"6..x,v753635"
11:13:19.693710 table@compaction created L2@6789 N·35173 S·2MiB "6..x,v925351":";..x,v2672418"
11:13:20.328155 table@compaction created L2@6790 N·35238 S·2MiB ";..x,v964018":"A..x,v3529098"
11:13:20.818787 table@compaction created L2@6791 N·35183 S·2MiB "A..x,v2686284":"G..x,v2574184"
11:13:21.513312 table@compaction created L2@6792 N·35187 S·2MiB "G..x,v460548":"L..x,v1064870"
11:13:22.119020 table@compaction created L2@6793 N·35181 S·2MiB "L..x,v3148":"R..x,v3062106"
11:13:22.815192 table@compaction created L2@6794 N·35186 S·2MiB "R..x,v1727046":"W..x,v1751928"
11:13:23.523246 table@compaction created L2@6795 N·35164 S·2MiB "W..x,v719737":"]..x,v1950508"
11:13:24.241929 table@compaction created L2@6796 N·35189 S·2MiB "]..x,v2544980":"c..x,v3669489"
11:13:24.888097 table@compaction created L2@6797 N·35174 S·2MiB "c..x,v2036611":"h..x,v743007"
11:13:24.911592 table@compaction created L2@6798 N·1481 S·86KiB "h..x,v2399741":"h..x,v2613619"
11:13:24.928807 table@compaction commited F~ S-68KiB D·1079 T·7.339848778s
11:13:24.928897 table@move L2@6341 -> L3
11:13:25.036031 table@move L2@6387 -> L3
11:13:25.060750 table@compaction L1·1 -> L2·7 S·12MiB Q·3702812
11:13:25.703861 table@compaction created L2@6799 N·35170 S·2MiB "\xdc..x,v2344889":"\xe1..x,v2968409"
11:13:26.346470 table@compaction created L2@6800 N·35171 S·2MiB "\xe1..x,v1530856":"\xe7..x,v469657"
11:13:26.555347 table@compaction created L2@6801 N·35181 S·2MiB "\xe7..x,v809525":"\xec..x,v1570038"
11:13:27.463430 table@compaction created L2@6802 N·35178 S·2MiB "\xec..x,v1732929":"\xf2..x,v509868"
11:13:28.065456 table@compaction created L2@6803 N·35190 S·2MiB "\xf2..x,v365336":"\xf8..x,v3159206"
11:13:28.583001 table@compaction created L2@6804 N·35158 S·2MiB "\xf8..\x00,v1081341":"\xfd..x,v1775515"
11:13:28.840038 table@compaction created L2@6805 N·14312 S·839KiB "\xfd..\x00,v46859":"\xff..\x00,v337135"
11:13:28.869562 table@compaction commited F-1 S-48KiB D·760 T·3.808716542s
11:13:28.909469 table@compaction L1·1 -> L2·11 S·20MiB Q·3705258
11:13:29.639580 table@compaction created L2@6806 N·35223 S·2MiB "\xa2..x,v2330722":"\xa8..x,v2308278"
11:13:30.354214 table@compaction created L2@6807 N·35158 S·2MiB "\xa8..x,v1272847":"\xad..x,v2876049"
11:13:30.980290 table@compaction created L2@6808 N·35198 S·2MiB "\xad..x,v2904549":"\xb3..x,v2154937"
11:13:31.802110 table@compaction created L2@6809 N·35184 S·2MiB "\xb3..x,v1383129":"\xb8..\x00,v249985"
11:13:32.472652 table@compaction created L2@6810 N·35168 S·2MiB "\xb8..x,v1268887":"\xbe..\x00,v981501"
11:13:33.037674 table@compaction created L2@6811 N·35180 S·2MiB "\xbe..x,v3026705":"\xc4..x,v3195517"
11:13:33.727637 table@compaction created L2@6812 N·35185 S·2MiB "\xc4..x,v1164499":"\xc9..x,v3184223"
11:13:34.414936 table@compaction created L2@6813 N·35201 S·2MiB "\xc9..x,v1357731":"\xcf..x,v3109412"

from goleveldb.

@dajohi Could you please try again with this patch:

diff --git a/leveldb/db_compaction.go b/leveldb/db_compaction.go
index 58c5348..eadc98b 100644
--- a/leveldb/db_compaction.go
+++ b/leveldb/db_compaction.go
@@ -10,6 +10,7 @@ import (
    "errors"
    "sync"
    "time"
+   "github.com/davecgh/go-spew/spew"

    "github.com/conformal/goleveldb/leveldb/memdb"
 )
@@ -275,6 +276,20 @@ func (d *DB) doCompaction(c *compaction, noTrivial bool) {
        stats[1].startTimer()
        iter := c.newIterator()
        defer iter.Release()
+
+       defer func() {
+           if x := recover(); x != nil {
+               if x != errTransactExiting {
+                   p := &spew.ConfigState{
+                       Indent: " ",
+                       MaxDepth: 7,
+                   }
+                   p.Dump(iter)
+               }
+               panic(x)
+           }
+       }()
+
        for i := 0; iter.Next(); i++ {
            // Skip until last state.
            if i < snapIter {

I have been try it myself but have not yet hit the panic so far.

from goleveldb.

starting to think this is a bad hardware or and OS bug. will reopen if i need to.

from goleveldb.

I have a problem in using leveldb in golang. I'm using leveldb for indexing books and words in a library program but when size of the library become huge (like 3000 books) adding a book gets too much time for indexing it. when profiling my program I undarestand that leveldb compaction gets a big part of time. Is there a way to defer compaction to the end of the program or when a book is deleted or something else to solve this problem?
thanks in advance

from goleveldb.