{"action":"created","issue":{"url":"https://api.github.com/repos/boltdb/bolt/issues/298","labels_url":"https://api.github.com/repos/boltdb/bolt/issues/298/labels{/name}","comments_url":"https://api.github.com/repos/boltdb/bolt/issues/298/comments","events_url":"https://api.github.com/repos/boltdb/bolt/issues/298/events","html_url":"https://github.com/boltdb/bolt/issues/298","id":56749298,"number":298,"title":"unreachable unfreed ","user":{"login":"alvarolm","id":2561547,"avatar_url":"https://avatars.githubusercontent.com/u/2561547?v=3","gravatar_id":"","url":"https://api.github.com/users/alvarolm","html_url":"https://github.com/alvarolm","followers_url":"https://api.github.com/users/alvarolm/followers","following_url":"https://api.github.com/users/alvarolm/following{/other_user}","gists_url":"https://api.github.com/users/alvarolm/gists{/gist_id}","starred_url":"https://api.github.com/users/alvarolm/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/alvarolm/subscriptions","organizations_url":"https://api.github.com/users/alvarolm/orgs","repos_url":"https://api.github.com/users/alvarolm/repos","events_url":"https://api.github.com/users/alvarolm/events{/privacy}","received_events_url":"https://api.github.com/users/alvarolm/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":13,"created_at":"2015-02-05T23:56:07Z","updated_at":"2015-08-28T21:41:19Z","closed_at":null,"body":"after doing 10 million Puts in one bucket of an empty database using as key a timestamp in nanoseconds and value 8 zero bytes with batches of 100 thousand everything ends fine during execution (I'm using https://github.com/boltdb/coalescer, with 1ms interval), no errors or nothing.\r\n\r\nstats just after Puts done:\r\n```\r\n(bolt.Stats) {\r\n FreePageN: (int) 0,\r\n PendingPageN: (int) 66317,\r\n FreeAlloc: (int) 271634432,\r\n FreelistInuse: (int) 530552,\r\n TxN: (int) 0,\r\n OpenTxN: (int) 0,\r\n TxStats: (bolt.TxStats) {\r\n  PageCount: (int) 4279034,\r\n  PageAlloc: (int) 17560088576,\r\n  CursorCount: (int) 10000204,\r\n  NodeCount: (int) 4164741,\r\n  NodeDeref: (int) 17049,\r\n  Rebalance: (int) 0,\r\n  RebalanceTime: (time.Duration) 0,\r\n  Split: (int) 114188,\r\n  Spill: (int) 4278932,\r\n  SpillTime: (time.Duration) 1m0.497335167s,\r\n  Write: (int) 4279136,\r\n  WriteTime: (time.Duration) 2m3.890396496s\r\n }\r\n}\r\n```\r\ncmd bolt stats\r\n```\r\nAggregate statistics for 1 buckets\r\n\r\nPage count statistics\r\n\tNumber of logical branch pages: 1022\r\n\tNumber of physical branch overflow pages: 0\r\n\tNumber of logical leaf pages: 113170\r\n\tNumber of physical leaf overflow pages: 0\r\nTree statistics\r\n\tNumber of keys/value pairs: 10000000\r\n\tNumber of levels in B+tree: 4\r\nPage size utilization\r\n\tBytes allocated for physical branch pages: 4186112\r\n\tBytes actually used for branch data: 2756936 (65%)\r\n\tBytes allocated for physical leaf pages: 463544320\r\n\tBytes actually used for leaf data: 321810720 (69%)\r\nBucket statistics\r\n\tTotal number of buckets: 1\r\n\tTotal number on inlined buckets: 0 (0%)\r\n\tBytes used for inlined buckets: 0 (0%)\r\n```\r\ncmd bolt check throws:\r\n```\r\npage 179173: unreachable unfreed\r\n1 errors found\r\n```\r\ncmd bolt pages | grep \"179173\":\r\n```\r\n179173   leaf       2\r\n```\r\ndb file: https://www.dropbox.com/s/b7fcmb9h050uzpr/dbx.tst.tar.gz?dl=0\r\n\r\n(I'm using the master branch at b8dbe1101d74c30e817227a99716591e3e6e6bc4)\r\nany ideas ?\r\n\r\n### how to reproduce the error:\r\ncmd bolt bench (using sequential keys returns 'OK'):\r\n```\r\nbolt bench --write-mode 'rnd' --count '10000000' --batch-size '100000' --work\r\nbolt check /tmp/bolt-bench-xxxxxxxx\r\n```\r\ncode:\r\n```Go\r\nfunc TestBolt0(t *testing.T) {\r\n\tdb := open()\r\n\tbucket := []byte(\"bucket\")\r\n\r\n\tif err := db.Update(func(tx *bolt.Tx) error {\r\n\t\t_, err := tx.CreateBucket(bucket)\r\n\t\tif err != nil {\r\n\t\t\treturn err\r\n\t\t}\r\n\t\treturn nil\r\n\t}); err != nil {\r\n\t\tt.Fatalf(\"update failed: %s\", err)\r\n\t}\r\n\r\n\tvar value []byte\r\n\tvar pkey []byte\r\n\tvalue = make([]byte, 8)\r\n\r\n\tfor i := 0; i < 100; i++ {\r\n\t\tfmt.Println(\"FLUSH N°\", i)\r\n\t\tdb.Update(func(tx *bolt.Tx) error {\r\n\t\t\tfor i := 0; i < 100000; i++ {\r\n\t\t\t\tpkey = NewKey()\r\n\t\t\t\tif err := tx.Bucket(bucket).Put(pkey, value); err != nil {\r\n\t\t\t\t\tt.Fatal(err)\r\n\t\t\t\t}\r\n\r\n\t\t\t}\r\n\t\t\treturn nil\r\n\t\t})\r\n\r\n\t}\r\n\r\n\tspew.Dump(db.Stats(), db.Path())\r\n\tspew.Dump(db)\r\n        db.Close()\r\n}\r\nfunc open() *bolt.DB {\r\n\tdb, err := bolt.Open(\"/tmp/dbx.tst\", 0600, nil)\r\n\tif err != nil {\r\n\t\tpanic(\"open: \" + err.Error())\r\n\t}\r\n\treturn db\r\n}\r\nfunc NewKey() (key []byte) {\r\n\tkey = make([]byte, 8)\r\n\tbinary.LittleEndian.PutUint64(key, uint64(time.Now().UnixNano()))\r\n\treturn\r\n}\r\n```\r\n### Hints:\r\n\r\nwhen trying two separate write instances of 5 million Puts in batches of 80 thousand+ each on the same database:\r\n```\r\nthe 1st instance:\r\nhas no execution errors\r\ncmd bolt check returns 'OK'.\r\n\r\nthe 2nd instance:\r\nhas no execution errors\r\ncmd bolt check returns one error: 'page XXXXXX: unreachable unfreed'\r\n```\r\ngeneral observations after trying different configurations:\r\n```\r\nbolt check returns one unreachable unfreed page error.\r\n```\r\n```\r\neven with strictMode set to true, no error, panic or anything shows up.\r\n```\r\n```\r\nerror appears when using batches of ~80 thousand or higher.\r\n```\r\n```\r\nerror appears only when using non sequential keys. \r\n```\r\n```\r\nerror appears when writing large records (~10 Million key value records and over)\r\n```\r\nim guessing is a capacity issue with freelist, maybe at the commit stage when the freelist is written to the disk it cuts the last page id ?\r\n## Update \r\n**even when the cmd tool reports that the database has one error, after checking the key and values stored they all seem intact with no errors occurring when reading it, why ?**\r\ncode:\r\n```Go\r\nfunc TestBolt0(t *testing.T) {\r\n\tdb := open()\r\n        db.StrictMode = true // even without StrictMode\r\n\tbucket := []byte(\"bucket\")\r\n\r\n\tif err := db.Update(func(tx *bolt.Tx) error {\r\n\t\t_, err := tx.CreateBucket(bucket)\r\n\t\tif err != nil {\r\n\t\t\treturn err\r\n\t\t}\r\n\t\treturn nil\r\n\t}); err != nil {\r\n\t\tt.Fatalf(\"update failed: %s\", err)\r\n\t}\r\n\r\n\tfmt.Println(\"WRITING\")\r\n\tlessTime := uint64(time.Now().UnixNano())\r\n\tvar valueCount uint64\r\n\tvar keySum uint64\r\n\tvar operations int = 10000000\r\n\tvar batchSize int = 100000\r\n\r\n\tfor i := 0; i < operations/batchSize; i++ {\r\n\t\tdb.Update(func(tx *bolt.Tx) error {\r\n\t\t\tfor i := 0; i < batchSize; i++ {\r\n\t\t\t\tvalue := make([]byte, 8)\r\n\t\t\t\tvalueCount++\r\n\t\t\t\tpkeyuint, pkey := NewKey(lessTime)\r\n\t\t\t\tkeySum = keySum + pkeyuint\r\n\t\t\t\tbinary.PutUvarint(value, valueCount)\r\n\t\t\t\t//fmt.Println(pkeyuint, valueCount)\r\n\t\t\t\tif err := tx.Bucket(bucket).Put(pkey, value); err != nil {\r\n\t\t\t\t\tt.Fatal(err)\r\n\t\t\t\t}\r\n\r\n\t\t\t}\r\n\t\t\treturn nil\r\n\t\t})\r\n\t\tfmt.Println(\"FLUSH N°\", i)\r\n\r\n\t}\r\n\r\n\tfmt.Println(\"keysum:\", keySum)\r\n\tspew.Dump(db.Stats())\r\n\tspew.Dump(db)\r\n\tdbfile := db.Path()\r\n\tdb.Close()\r\n\r\n\ttime.Sleep(3 * time.Second)\r\n\r\n\tdb, err := bolt.Open(dbfile, 0600, nil)\r\n\tif err != nil {\r\n\t\tpanic(\"open: \" + err.Error())\r\n\t}\r\n\r\n\tvar vsumtotal uint64\r\n\tvar ksumtotal uint64\r\n\r\n\tfmt.Println(\"READING\")\r\n\tdb.View(func(tx *bolt.Tx) error {\r\n\t\tb := tx.Bucket([]byte(bucket))\r\n\t\tc := b.Cursor()\r\n\r\n\t\tfor k, v := c.First(); k != nil; k, v = c.Next() {\r\n\t\t\tif val, n := binary.Uvarint(v); n <= 0 {\r\n\t\t\t\tt.Fatal(err)\r\n\t\t\t} else {\r\n\t\t\t\t//fmt.Println(\"val\", val)\r\n\t\t\t\tvsumtotal = vsumtotal + val\r\n\t\t\t}\r\n\t\t\tif key, n := binary.Uvarint(k); n <= 0 {\r\n\t\t\t\tt.Fatal(err)\r\n\t\t\t} else {\r\n\t\t\t\t//fmt.Println(\"key\", key)\r\n\t\t\t\tksumtotal = ksumtotal + key\r\n\t\t\t}\r\n\r\n\t\t}\r\n\r\n\t\treturn nil\r\n\t})\r\n\r\n\tp1 := operations + 1\r\n\tp2 := operations * p1\r\n\tvalueSum := uint64(p2 / 2)\r\n\tif vsumtotal != valueSum {\r\n\t\tt.Error(\"Value sum error, got\", valueSum, \" instead:\", vsumtotal)\r\n\t}\r\n\tif ksumtotal != keySum {\r\n\t\tt.Error(\"Key sum error, got\", keySum, \" instead:\", ksumtotal)\r\n\t}\r\n\tfmt.Println(vsumtotal)\r\n\tspew.Dump(db.Stats())\r\n\tspew.Dump(db)\r\n\r\n\tif err := db.View(func(tx *bolt.Tx) error {\r\n\t\tvar count int\r\n\t\tch := tx.Check()\r\n\tloop:\r\n\t\tfor {\r\n\t\t\tselect {\r\n\t\t\tcase err, ok := <-ch:\r\n\t\t\t\tif !ok {\r\n\t\t\t\t\tbreak loop\r\n\t\t\t\t}\r\n\t\t\t\tfmt.Println(err)\r\n\t\t\t\tcount++\r\n\t\t\t}\r\n\t\t}\r\n\r\n\t\t// Print summary of errors.\r\n\t\tif count > 0 {\r\n\t\t\tt.Fatalf(\"%d errors found\", count)\r\n\t\t} else {\r\n\t\t\tfmt.Println(\"OK\")\r\n\t\t}\r\n\t\treturn nil\r\n\t}); err != nil {\r\n\t\tt.Fatal(err)\r\n\t}\r\n\r\n\t//closedb(db)\r\n}\r\nfunc NewKey(less uint64) (keyUint uint64, keyBytes []byte) {\r\n\tkeyBytes = make([]byte, 8)\r\n\tkeyUint = uint64(time.Now().UnixNano()) - less\r\n\tbinary.PutUvarint(keyBytes, keyUint)\r\n\treturn\r\n}\r\n\r\nfunc tempfile() string {\r\n\tf, _ := ioutil.TempFile(\"\", \"coalescer-\")\r\n\tpath := f.Name()\r\n\tf.Close()\r\n\tos.Remove(path)\r\n\treturn path\r\n}\r\n\r\nfunc open() *bolt.DB {\r\n\tdb, err := bolt.Open(tempfile(), 0600, nil)\r\n\tif err != nil {\r\n\t\tpanic(\"open: \" + err.Error())\r\n\t}\r\n\treturn db\r\n}\r\n\r\nfunc closedb(db *bolt.DB) {\r\n\tif db == nil {\r\n\t\treturn\r\n\t}\r\n\tpath := db.Path()\r\n\tdb.Close()\r\n\tif path != \"\" {\r\n\t\tos.Remove(path)\r\n\t}\r\n}\r\n```\r\n###### https://groups.google.com/d/msg/influxdb/eL-ijjcQnNg/MDFQtiZxSfkJ ? \r\n(ref https://github.com/boltdb/bolt/issues/301)"},"comment":{"url":"https://api.github.com/repos/boltdb/bolt/issues/comments/135894962","html_url":"https://github.com/boltdb/bolt/issues/298#issuecomment-135894962","issue_url":"https://api.github.com/repos/boltdb/bolt/issues/298","id":135894962,"user":{"login":"xiang90","id":4479947,"avatar_url":"https://avatars.githubusercontent.com/u/4479947?v=3","gravatar_id":"","url":"https://api.github.com/users/xiang90","html_url":"https://github.com/xiang90","followers_url":"https://api.github.com/users/xiang90/followers","following_url":"https://api.github.com/users/xiang90/following{/other_user}","gists_url":"https://api.github.com/users/xiang90/gists{/gist_id}","starred_url":"https://api.github.com/users/xiang90/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/xiang90/subscriptions","organizations_url":"https://api.github.com/users/xiang90/orgs","repos_url":"https://api.github.com/users/xiang90/repos","events_url":"https://api.github.com/users/xiang90/events{/privacy}","received_events_url":"https://api.github.com/users/xiang90/received_events","type":"User","site_admin":false},"created_at":"2015-08-28T21:41:19Z","updated_at":"2015-08-28T21:41:19Z","body":"@cep21 Have you tried to find the root cause?"}}