Skip to content
This repository has been archived by the owner on Mar 9, 2019. It is now read-only.

Windows: default options limit database to 64MB. #504

Closed
ChrisHines opened this issue Feb 2, 2016 · 16 comments
Closed

Windows: default options limit database to 64MB. #504

ChrisHines opened this issue Feb 2, 2016 · 16 comments

Comments

@ChrisHines
Copy link
Contributor

Environment:

OS: Windows 7
Go: go version go1.5.1 windows/amd64

Steps to reproduce:

  1. Open a new database with nil options.
  2. Create a bucket
  3. Repeatedly put new key/value pairs into the bucket.

What happens:

The database file quickly grows to 64MB and then bolt returns an error:

file resize error: truncate test.db: The requested operation cannot be performed on a file with a user-mapped section open.

Workarounds: The error does not occur if the database is opened with the NoGrowSync option enabled.

What was expected: The default options should work better on all platforms.

@schollz
Copy link

schollz commented Feb 4, 2016

Thanks for the workaround, I also ran into this issue yesterday (Windows 10, go1.5.1 windows/amd64) and had a hard time finding the fix.

How should this work for cross-compilation? The docs indicate that NoGrowSync=true is only safe on non-ext3/ext4 systems. Should one detect the filesystem before proceeding?

@DavidVorick
Copy link

We have been using bolt for a while and our users haven't reported this issue. Our database right now gets to about 500MB in size, well beyond that 64MB that you are reporting returns an error.

There must be other conditions that are causing the problem? We are not changing the default values for NoGrowSync. Or do you mean that you are adding more than 64MB in a single transaction?

@ChrisHines
Copy link
Contributor Author

I don't know what other conditions may be causing the problem. It happens 100% of the time for me from more than one set of code doing different sized transactions. The following code reproduces the problem for me:

package main

import (
    "encoding/binary"
    "log"

    "github.com/boltdb/bolt"
)

func panicOnErr(err error) {
    if err != nil {
        panic(err)
    }
}

var bkt = []byte("bucket1")
var data = []byte("01234567890123456789012345678901")

type ID uint64

func (id ID) Bytes() []byte {
    buf := make([]byte, binary.Size(id))
    binary.BigEndian.PutUint64(buf, uint64(id))
    return buf
}

func main() {
    db, err := bolt.Open("test.db", 0644, nil)
    panicOnErr(err)
    defer db.Close()

    db.Update(func(tx *bolt.Tx) error {
        _, err := tx.CreateBucketIfNotExists(bkt)
        panicOnErr(err)
        return nil
    })

    for i := 0; ; i++ {
        err := db.Update(func(tx *bolt.Tx) error {
            b := tx.Bucket(bkt)
            for i := 0; i < 1000; i++ {
                ns, _ := b.NextSequence()
                k := ID(ns)
                err := b.Put(k.Bytes(), data)
                panicOnErr(err)
                if i == 0 {
                    log.Println(k)
                }
            }
            return nil
        })
        panicOnErr(err)
    }
}

Trimmed output:

2016/02/04 23:02:38 1
2016/02/04 23:02:38 1001
2016/02/04 23:02:38 2001
2016/02/04 23:02:38 3001
2016/02/04 23:02:38 4001
2016/02/04 23:02:39 5001
2016/02/04 23:02:39 6001
2016/02/04 23:02:39 7001
2016/02/04 23:02:39 8001
.
.
<snip>
.
.
2016/02/04 23:03:05 357001
2016/02/04 23:03:05 358001
2016/02/04 23:03:05 359001
2016/02/04 23:03:05 360001
2016/02/04 23:03:06 361001
2016/02/04 23:03:06 362001
2016/02/04 23:03:06 363001
2016/02/04 23:03:06 364001
panic: file resize error: truncate test.db: The requested operation cannot be performed on a file with a user-mapped section open.

goroutine 1 [running]:
main.panicOnErr(0x2140028, 0xc082176f90)
        C:/Users/Chris/Go/src/testseq/testbolt.go:12 +0x52
main.main()
        C:/Users/Chris/Go/src/testseq/testbolt.go:52 +0x114

C:\temp>dir test.db
...
02/04/2016  11:03 PM        67,108,864 test.db

C:\temp>bolt stats test.db
Aggregate statistics for 1 buckets

Page count statistics
        Number of logical branch pages: 121
        Number of physical branch overflow pages: 0
        Number of logical leaf pages: 10111
        Number of physical leaf overflow pages: 0
Tree statistics
        Number of keys/value pairs: 364000
        Number of levels in B+tree: 3
Page size utilization
        Bytes allocated for physical branch pages: 495616
        Bytes actually used for branch data: 247480 (49%)
        Bytes allocated for physical leaf pages: 41414656
        Bytes actually used for leaf data: 20545776 (49%)
Bucket statistics
        Total number of buckets: 1
        Total number on inlined buckets: 0 (0%)
        Bytes used for inlined buckets: 0 (0%)

@benbjohnson
Copy link
Member

@ChrisHines Can you try with this commit: 852d302

I believe the issue is caused by this commit: #453

I need to get better CI running so that non-Unix platforms can be tested regularly (Windows, ARM, etc). I don't have access to a Windows machine so it's difficult for me to test every pull request.

@ChrisHines
Copy link
Contributor Author

@benbjohnson That commit does not exhibit the problem. I modified the code I posted above to drive a git bisect and got this bisect log:

Update: Ignore this bisect log, it was buggy.

$ git bisect log
git bisect start
bad: [ee4a088] Merge pull request #492 from boltdb/revert-491-arm64
good: [852d302] skip empty pages during cursor seek
good: [8b08bd4] test suite refactoring
bad: [02c43da] Merge pull request #481 from gyuho/boltdb_typo
good: [694a82a] Merge branch 'grow' of https://github.com/xiang90/bolt into xiang90-grow
bad: [d8b06c0] Merge branch 'xiang90-grow'
good: [a122e1c] add AllocSize, minor grow() refactor
first bad commit: [d8b06c0] Merge branch 'xiang90-grow'

I have manually confirmed this result.

@ChrisHines
Copy link
Contributor Author

@benbjohnson after a bit more digging, I found a bug in my bisect driver. Fixing the bug and re-running the bisect, I now get this log:

git bisect start
bad: [2f846c3] Merge pull request #508 from hermanschaaf/patch-1
good: [852d302] skip empty pages during cursor seek
good: [34a0fa5] Merge pull request #477 from benbjohnson/testing
bad: [ed54c47] Merge pull request #478 from TrevorSStone/master
bad: [d8b06c0] Merge branch 'xiang90-grow'
good: [25b2810] Merge pull request #479 from azazeal/master
good: [694a82a] Merge branch 'grow' of https://github.com/xiang90/bolt into xiang90-grow
bad: [a122e1c] add AllocSize, minor grow() refactor
first bad commit: [a122e1c] add AllocSize, minor grow() refactor

Sorry for the confusion.

@xiang90
Copy link
Contributor

xiang90 commented Feb 7, 2016

@ChrisHines Did you run the bisect multiple times to make sure the result is reliable?

@benbjohnson
Copy link
Member

@xiang90 I think we'll need to close the db.file handle while growing for Windows machines. I would expect this to be the commit that changed this behavior (since grow() is now separate from mmap()):

d8b06c0

@xiang90
Copy link
Contributor

xiang90 commented Feb 7, 2016

@benbjohnson You are probably right. I see windows has separate logic for handling mmap+grow. I do not have access to windows machines at the moment unfortunately.

@ChrisHines
Copy link
Contributor Author

@benbjohnson @xiang90 Yes, I can reproduce the problem every time on a122e1c and it does not reproduce on 694a82a.

@ChrisHines
Copy link
Contributor Author

After looking at the commits in question more carefully, I noticed that the first bad commit (a122e1c) added a (previously missing) error check to the call to grow in Tx.Commit (see a122e1c#diff-8624b8c3952f1cd26aa8ffc37e653eabR189). So I rolled back to to the last good commit (694a82a) and added just that error check. Sure enough it failed where before it had been "succeeding". So it looks like the error was happening all along but had been ignored.

@ChrisHines
Copy link
Contributor Author

Researching the OS calls in play os.File.Truncate on Windows eventually calls SetEndOfFile, this paragraph from the MSDN docs seems relevant:

If CreateFileMapping is called to create a file mapping object for hFile, UnmapViewOfFile must be called first to unmap all views and call CloseHandle to close the file mapping object before you can call SetEndOfFile.

@ChrisHines
Copy link
Contributor Author

This bug seems to be caught by the current test suite. TestDB_Put_VeryLarge fails on master as follows:

C:\Users\Chris\Go\src\github.com\boltdb\bolt>go test
seed: 0
quick settings: count=5, items=1000, ksize=1024, vsize=1024
00010000000000000000000000000000
--- FAIL: TestDB_Put_VeryLarge (7.04s)
        bucket_test.go:194: file resize error: truncate C:\Users\Chris\AppData\Local\Temp\bolt-842929913: The requested operation cannot be performed on a file with a user-mapped section open.
panic: file resize error: truncate C:\Users\Chris\AppData\Local\Temp\bolt-842929913: The requested operation cannot be performed on a file with a user-mapped section open. [recovered]
        panic: file resize error: truncate C:\Users\Chris\AppData\Local\Temp\bolt-842929913: The requested operation cannot be performed on a file with a user-mapped section open.

goroutine 36 [running]:
testing.tRunner.func1(0xc08212d710)
        c:/go/src/testing/testing.go:450 +0x178
github.com/boltdb/bolt_test.(*DB).MustCheck(0xc082024040)
        C:/Users/Chris/Go/src/github.com/boltdb/bolt/db_test.go:1590 +0xd2
github.com/boltdb/bolt_test.(*DB).Close(0xc082024040, 0x0, 0x0)
        C:/Users/Chris/Go/src/github.com/boltdb/bolt/db_test.go:1527 +0x55
github.com/boltdb/bolt_test.(*DB).MustClose(0xc082024040)
        C:/Users/Chris/Go/src/github.com/boltdb/bolt/db_test.go:1536 +0x28
runtime.Goexit()
        c:/go/src/runtime/panic.go:320 +0x109
testing.(*common).FailNow(0xc08212d710)
        c:/go/src/testing/testing.go:336 +0x3d
testing.(*common).Fatal(0xc08212d710, 0xc084475eb8, 0x1, 0x1)
        c:/go/src/testing/testing.go:373 +0x76
github.com/boltdb/bolt_test.TestDB_Put_VeryLarge(0xc08212d710)
        C:/Users/Chris/Go/src/github.com/boltdb/bolt/bucket_test.go:194 +0x2e5
testing.tRunner(0xc08212d710, 0x769b70)
        c:/go/src/testing/testing.go:456 +0x9f
created by testing.RunTests
        c:/go/src/testing/testing.go:561 +0x874

goroutine 1 [chan receive]:
testing.RunTests(0x6afb28, 0x769960, 0x91, 0x91, 0x3a4401)
        c:/go/src/testing/testing.go:562 +0x8b4
testing.(*M).Run(0xc0824dbef8, 0xc082002910)
        c:/go/src/testing/testing.go:494 +0x77
main.main()
        github.com/boltdb/bolt/_test/_testmain.go:378 +0x11d
exit status 2
FAIL    github.com/boltdb/bolt  9.078s

@DavidVorick
Copy link

I earlier stated that our users had not been running into this issue, although it appears that I have spoken too soon. They have started reporting this issue. Sorry for the confusion.

@ChrisHines
Copy link
Contributor Author

I confirm this issue is fixed on master.

@benbjohnson
Copy link
Member

@ChrisHines Thanks for checking on it and closing the issue.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants