scan timeout with incremental mutation

• • • From the attached zip, look for indexer.log.3 in n_1.
    • A new scan happen at about the same time when a new TS is to be generated.

08:51:03.123841 [Info] ScanCoordinator: SCAN_REQ scan id: 94, defnId: 15868169058065409, index: default/index_newField, type: scanall, span: all pagesize: 1 limit: 10000000
08:51:03.765831 [Debug] Timekeeper::generateNewStabilityTS

• • • The log is then followed by pprof. One of the go-routine shows that scan coordinator is either waiting for scan timeout or a new snapshot.

1 @ 0x4015e09 0x4020130 0x401fd62 0x40b994b 0x40e8a5e 0x42bf2b1 0x40160a0

1. 0x4020130 selectgo+0x3a0 /private/var/folders/00/0sdwh000h01000cxqpysvccm0035qk/T/makerelease003761064/go/src/pkg/runtime/chan.goc:804
2. 0x401fd62 runtime.selectgo+0x12 /private/var/folders/00/0sdwh000h01000cxqpysvccm0035qk/T/makerelease003761064/go/src/pkg/runtime/chan.goc:647
3. 0x40b994b github.com/couchbase/indexing/secondary/indexer.(*scanCoordinator).requestHandler+0x1c6b /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/scan_coordinator.go:603
4. 0x40e8a5e github.com/couchbase/indexing/secondary/indexer.*scanCoordinator.(github.com/couchbase/indexing/secondary/indexer.requestHandler)·fm+0x4e /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/scan_coordinator.go:322
5. 0x42bf2b1 github.com/couchbase/indexing/secondary/queryport.(*Server).handleConnection+0x641 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/queryport/server.go:156

• • • We also see that a new snapshot is in the process of being created. The snapshot creation is blocked for all worker to be done for flushing mutations.

1 @ 0x4015e09 0x4015e8b 0x401f1a8 0x401f62e 0x407bd8b 0x40c41e9 0x40160a0

1. 0x401f1a8 chanrecv+0x1d8 /private/var/folders/00/0sdwh000h01000cxqpysvccm0035qk/T/makerelease003761064/go/src/pkg/runtime/chan.goc:298
2. 0x401f62e runtime.chanrecv2+0x3e /private/var/folders/00/0sdwh000h01000cxqpysvccm0035qk/T/makerelease003761064/go/src/pkg/runtime/chan.goc:358
3. 0x407bd8b github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).NewSnapshot+0xbb /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:617
4. 0x40c41e9 github.com/couchbase/indexing/secondary/indexer.(*storageMgr).createSnapshotWorker+0x11a9 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/storage_manager.go:291

• • • Another go-routine also show that flushing is going on.

1 @ 0x40068e5 0x4068f41 0x406672c 0x4077834 0x40774b6 0x40770da 0x40160a0

1. 0x4068f41 github.com/couchbase/indexing/secondary/fdb._Cfunc_fdb_get_kv+0x31 github.com/couchbase/indexing/secondary/fdb/_obj/_cgo_defun.c:226
2. 0x406672c github.com/couchbase/indexing/secondary/fdb.(*KVStore).GetKV+0x23c /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/fdb/kv.go:35
3. 0x4077834 github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).insertPrimaryIndex+0x334 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:269
4. 0x40774b6 github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).insert+0x76 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:250
5. 0x40770da github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).handleCommandsWorker+0x31a /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:218

• • • The log does not show when the flush is completed (> 2 min?) But scan timeout after the pprof is printed.

08:53:03.123858 [Info] ScanCoordinator: SCAN_REQ: scan id: 94, defnId: 15868169058065409, index: default/index_newField, type: scanall, span: all pagesize: 1 limit: 10000000, Error (Index scan timed out)

• • • Note that after 1s, a second pprof is printed, it still show that the worker is doing a flush.

08:53:15.938232 [Debug] goroutine profile: total 176

1 @ 0x40068e5 0x4068f41 0x406672c 0x4077834 0x40774b6 0x40770da 0x40160a0

1. 0x4068f41 github.com/couchbase/indexing/secondary/fdb._Cfunc_fdb_get_kv+0x31 github.com/couchbase/indexing/secondary/fdb/_obj/_cgo_defun.c:226
2. 0x406672c github.com/couchbase/indexing/secondary/fdb.(*KVStore).GetKV+0x23c /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/fdb/kv.go:35
3. 0x4077834 github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).insertPrimaryIndex+0x334 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:269
4. 0x40774b6 github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).insert+0x76 /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:250
5. 0x40770da github.com/couchbase/indexing/secondary/indexer.(*fdbSlice).handleCommandsWorker+0x31a /Users/jliang/Documents/eclipse/sherlock/sherlock/goproj/src/github.com/couchbase/indexing/secondary/indexer/forestdb_slice_writer.go:218

• • • The log also indicate that there is simultanous mutations coming in.

08:53:04.222919 [Info] MutationStreamReader::logPerfStat
MutationCount 540000
08:53:05.078823 [Debug] Timekeeper::generateNewStabilityTS

08:53:05.369605 [Info] MutationStreamReader::logPerfStat
MutationCount 550000
08:53:06.078896 [Debug] Timekeeper::generateNewStabilityTS