etcd-4006-trace.txt

$ cd etcd
$ git checkout a907ca5e62503e9ee2f3db95024f00e92e374586 (Dec 16, 2015)
$ ./test
2015/12/16 05:43:24 store.index: compact 1
2015/12/16 05:43:24 store.index: compact 2
2015/12/16 05:43:24 store.index: compact 3
2015/12/16 05:43:24 store.index: compact 4
2015/12/16 05:43:24 store.index: compact 5
2015/12/16 05:43:24 store.index: compact 6
2015/12/16 05:43:24 store.index: compact 7
2015/12/16 05:43:24 store.index: compact 8
2015/12/16 05:43:24 store.index: compact 9
2015/12/16 05:43:24 store.index: compact 10
2015/12/16 05:43:24 store.index: compact 11
2015/12/16 05:43:24 store.index: compact 12
2015/12/16 05:43:24 store.index: compact 13
2015/12/16 05:43:24 store.index: compact 14
2015/12/16 05:43:24 store.index: compact 15
2015/12/16 05:43:24 store.index: compact 16
2015/12/16 05:43:24 store.index: compact 17
2015/12/16 05:43:24 store.index: compact 18
2015/12/16 05:43:24 store.index: compact 19
2015/12/16 05:43:24 store.index: compact 1
2015/12/16 05:43:24 store.index: compact 2
2015/12/16 05:43:24 store.index: compact 3
2015/12/16 05:43:24 store.index: compact 4
2015/12/16 05:43:24 store.index: compact 5
2015/12/16 05:43:24 store.index: compact 6
2015/12/16 05:43:24 store.index: compact 7
2015/12/16 05:43:24 store.index: compact 8
2015/12/16 05:43:24 store.index: compact 9
2015/12/16 05:43:24 store.index: compact 10
2015/12/16 05:43:24 store.index: compact 11
2015/12/16 05:43:24 store.index: compact 12
2015/12/16 05:43:24 store.index: compact 13
2015/12/16 05:43:24 store.index: compact 14
2015/12/16 05:43:24 store.index: compact 15
2015/12/16 05:43:24 store.index: compact 16
2015/12/16 05:43:24 store.index: compact 17
2015/12/16 05:43:24 store.index: compact 18
2015/12/16 05:43:24 store.index: compact 19
2015/12/16 05:43:25 store.index: compact 3
2015/12/16 05:43:25 store.index: compact 3
2015/12/16 05:43:31 store.index: compact 0
2015/12/16 05:43:32 store.index: compact 1
2015/12/16 05:43:32 store.index: compact 2
2015/12/16 05:43:32 store.index: compact 3
2015/12/16 05:43:32 store.index: compact 0
2015/12/16 05:43:32 store.index: compact 1
2015/12/16 05:43:32 store.index: compact 3
2015/12/16 05:43:34 store.index: compact 1
2015/12/16 05:43:34 storage: restore compact to 1
2015/12/16 05:43:35 storage: restore compact to 2
2015/12/16 05:43:35 store.index: compact 3
2015/12/16 05:43:36 storage: resume scheduled compaction at 2
2015/12/16 05:43:36 store.index: compact 2
2015/12/16 05:43:38 store.index: compact 1
2015/12/16 05:43:38 store.index: compact 2
2015/12/16 05:43:38 store.index: compact 3
2015/12/16 05:43:38 store.index: compact 4
2015/12/16 05:43:38 store.index: compact 5
2015/12/16 05:43:38 store.index: compact 6
2015/12/16 05:43:38 store.index: compact 7
2015/12/16 05:43:38 store.index: compact 8
2015/12/16 05:43:38 store.index: compact 9
2015/12/16 05:43:38 store.index: compact 10
2015/12/16 05:43:38 store.index: compact 11
2015/12/16 05:43:38 store.index: compact 12
2015/12/16 05:43:38 store.index: compact 13
2015/12/16 05:43:38 store.index: compact 14
2015/12/16 05:43:38 store.index: compact 15
2015/12/16 05:43:38 store.index: compact 16
2015/12/16 05:43:38 store.index: compact 17
2015/12/16 05:43:38 store.index: compact 18
2015/12/16 05:43:38 store.index: compact 19
2015/12/16 05:43:38 store.index: compact 1
2015/12/16 05:43:38 store.index: compact 2
2015/12/16 05:43:38 store.index: compact 3
2015/12/16 05:43:38 store.index: compact 4
2015/12/16 05:43:38 store.index: compact 5
2015/12/16 05:43:38 store.index: compact 6
2015/12/16 05:43:38 store.index: compact 7
2015/12/16 05:43:38 store.index: compact 8
2015/12/16 05:43:38 store.index: compact 9
2015/12/16 05:43:38 store.index: compact 10
2015/12/16 05:43:38 store.index: compact 11
2015/12/16 05:43:38 store.index: compact 12
2015/12/16 05:43:38 store.index: compact 13
2015/12/16 05:43:38 store.index: compact 14
2015/12/16 05:43:38 store.index: compact 15
2015/12/16 05:43:38 store.index: compact 16
2015/12/16 05:43:38 store.index: compact 17
2015/12/16 05:43:38 store.index: compact 18
2015/12/16 05:43:38 store.index: compact 19
2015/12/16 05:43:39 store.index: compact 3
2015/12/16 05:43:40 store.index: compact 3
2015/12/16 05:43:48 store.index: compact 0
2015/12/16 05:43:48 store.index: compact 1
2015/12/16 05:43:48 store.index: compact 2
2015/12/16 05:43:48 store.index: compact 3
2015/12/16 05:43:48 store.index: compact 0
2015/12/16 05:43:48 store.index: compact 1
2015/12/16 05:43:49 store.index: compact 3
2015/12/16 05:43:51 store.index: compact 1
2015/12/16 05:43:52 storage: restore compact to 1
2015/12/16 05:43:55 storage: restore compact to 2
2015/12/16 05:43:56 store.index: compact 3
2015/12/16 05:43:57 storage: resume scheduled compaction at 2
2015/12/16 05:43:57 store.index: compact 2
panic: test timed out after 3m0s

goroutine 301 [running]:
testing.startAlarm.func1()
        /usr/lib/go/src/testing/testing.go:703 +0x16b
created by time.goFunc
        /usr/lib/go/src/time/sleep.go:129 +0x6e

goroutine 1 [chan receive, 2 minutes]:
testing.RunTests(0xb41c90, 0xcfa9c0, 0x3f, 0x3f, 0x9a1801)
        /usr/lib/go/src/testing/testing.go:562 +0xafa
testing.(*M).Run(0xc820039f10, 0xcfdce0)
        /usr/lib/go/src/testing/testing.go:494 +0xe5
main.main()
        github.com/coreos/etcd/storage/_test/_testmain.go:252 +0x385

goroutine 17 [syscall, 2 minutes, locked to thread]:
runtime.goexit()
        /usr/lib/go/src/runtime/asm_amd64.s:1696 +0x1

goroutine 153 [syscall]:
syscall.Syscall(0x4b, 0x3, 0x0, 0x0, 0x4629d4, 0x698907, 0x4629d4)
        /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.Fdatasync(0x3, 0x0, 0x0)
        /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:472 +0x58
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.fdatasync(0xc8203de680, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/bolt_linux.go:9 +0x64
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).write(0xc82031e380, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:473 +0x71e
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).Commit(0xc82031e380, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:187 +0x7ba
github.com/coreos/etcd/storage/backend.(*batchTx).commit(0xc82040c260, 0xb41c00)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:135 +0xa0
github.com/coreos/etcd/storage/backend.(*batchTx).Commit(0xc82040c260)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:113 +0x74
github.com/coreos/etcd/storage/backend.(*backend).run(0xc8203e4ac0)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:144 +0x159
created by github.com/coreos/etcd/storage/backend.newBackend
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:79 +0x436

goroutine 300 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc82016c364)
        /usr/lib/go/src/runtime/sema.go:43 +0x26
sync.(*Mutex).Lock(0xc82016c360)
        /usr/lib/go/src/sync/mutex.go:82 +0x1ee
github.com/coreos/etcd/storage/backend.(*batchTx).Lock(0xc82016c360)
        <autogenerated>:1 +0x4c
github.com/coreos/etcd/storage.(*store).scheduleCompaction(0xc8204ecb40, 0x2, 0xc8204f9080)
        github.com/coreos/etcd/storage/_test/_obj_test/kvstore_compaction.go:42 +0x592
created by github.com/coreos/etcd/storage.(*store).Compact
        github.com/coreos/etcd/storage/_test/_obj_test/kvstore.go:336 +0x4f2

goroutine 176 [select]:
github.com/coreos/etcd/storage/backend.(*backend).run(0xc820435f40)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:138 +0x1d5
created by github.com/coreos/etcd/storage/backend.newBackend
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:79 +0x436

goroutine 181 [select]:
github.com/coreos/etcd/storage.(*watchableStore).syncWatchingsLoop(0xc820494740)
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:281 +0x21e
created by github.com/coreos/etcd/storage.newWatchableStore
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:66 +0x252

goroutine 172 [syscall]:
syscall.Syscall(0x4b, 0x4, 0x0, 0x0, 0x4629d4, 0x698907, 0x4629d4)
        /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.Fdatasync(0x4, 0x0, 0x0)
        /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:472 +0x58
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.fdatasync(0xc8203df040, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/bolt_linux.go:9 +0x64
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).write(0xc8201e5500, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:473 +0x71e
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).Commit(0xc8201e5500, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:187 +0x7ba
github.com/coreos/etcd/storage/backend.(*batchTx).commit(0xc82047e1c0, 0xb41c00)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:135 +0xa0
github.com/coreos/etcd/storage/backend.(*batchTx).Commit(0xc82047e1c0)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:113 +0x74
github.com/coreos/etcd/storage/backend.(*backend).run(0xc8204359c0)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:144 +0x159
created by github.com/coreos/etcd/storage/backend.newBackend
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:79 +0x436

goroutine 322 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc82016c364)
        /usr/lib/go/src/runtime/sema.go:43 +0x26
sync.(*Mutex).Lock(0xc82016c360)
        /usr/lib/go/src/sync/mutex.go:82 +0x1ee
github.com/coreos/etcd/storage/backend.(*batchTx).Lock(0xc82016c360)
        <autogenerated>:1 +0x4c
github.com/coreos/etcd/storage.TestRestoreContinueUnfinishedCompaction(0xc8203813b0)
        /etcd/gopath/src/github.com/coreos/etcd/storage/kvstore_test.go:655 +0x704
testing.tRunner(0xc8203813b0, 0xcfaf00)
        /usr/lib/go/src/testing/testing.go:456 +0xdd
created by testing.RunTests
        /usr/lib/go/src/testing/testing.go:561 +0xaa4

goroutine 186 [select]:
github.com/coreos/etcd/storage.(*watchableStore).syncWatchingsLoop(0xc820434480)
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:281 +0x21e
created by github.com/coreos/etcd/storage.newWatchableStore
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:66 +0x252

goroutine 189 [select]:
github.com/coreos/etcd/storage.(*watchableStore).syncWatchingsLoop(0xc820434cc0)
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:281 +0x21e
created by github.com/coreos/etcd/storage.newWatchableStore
        github.com/coreos/etcd/storage/_test/_obj_test/watchable_store.go:66 +0x252

goroutine 309 [syscall]:
syscall.Syscall(0x4b, 0x6, 0x0, 0x0, 0x4629d4, 0x698907, 0x4629d4)
        /usr/lib/go/src/syscall/asm_linux_amd64.s:18 +0x5
syscall.Fdatasync(0x6, 0x0, 0x0)
        /usr/lib/go/src/syscall/zsyscall_linux_amd64.go:472 +0x58
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.fdatasync(0xc8203df520, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/bolt_linux.go:9 +0x64
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).write(0xc8201e55e0, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:473 +0x71e
github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt.(*Tx).Commit(0xc8201e55e0, 0x0, 0x0)
        /etcd/gopath/src/github.com/coreos/etcd/Godeps/_workspace/src/github.com/boltdb/bolt/tx.go:187 +0x7ba
github.com/coreos/etcd/storage/backend.(*batchTx).commit(0xc82039c460, 0xb41c00)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:135 +0xa0
github.com/coreos/etcd/storage/backend.(*batchTx).Commit(0xc82039c460)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:113 +0x74
github.com/coreos/etcd/storage/backend.(*backend).run(0xc820274800)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:144 +0x159
created by github.com/coreos/etcd/storage/backend.newBackend
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:79 +0x436

goroutine 323 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc82016c364)
        /usr/lib/go/src/runtime/sema.go:43 +0x26
sync.(*Mutex).Lock(0xc82016c360)
        /usr/lib/go/src/sync/mutex.go:82 +0x1ee
github.com/coreos/etcd/storage/backend.(*batchTx).Commit(0xc82016c360)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/batch_tx.go:111 +0x3a
github.com/coreos/etcd/storage/backend.(*backend).run(0xc820160cc0)
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:144 +0x159
created by github.com/coreos/etcd/storage/backend.newBackend
        /etcd/gopath/src/github.com/coreos/etcd/storage/backend/backend.go:79 +0x436
FAIL    github.com/coreos/etcd/storage  180.032s