Mysterious exit redux

[benmargolin]

Please follow the steps below to help us help you.

1. Please supply the header (i.e. the first few lines) of your most recent
   log file for each node in your cluster. On most unix-based systems
   running with defaults, this boils down to the output of

   grep -F '[config]' cockroach-data/logs/cockroach.INFO

   When log files are not available, supply the output of cockroach version
   and all flags/environment variables passed to cockroach start instead.

I161206 21:45:08.553476 1 util/log/clog.go:1002 [config] file created at: 2016/12/06 21:45:08
I161206 21:45:08.553476 1 util/log/clog.go:1002 [config] running on machine: sonicfe
I161206 21:45:08.553476 1 util/log/clog.go:1002 [config] binary: CockroachDB beta-20161201 (linux amd64, built 2016/12/01 18:32:34, go1.7.3)
I161206 21:45:08.553476 1 util/log/clog.go:1002 [config] arguments: [cockroach start --store=/home/sonic/cockroach-data/ --http-port 8280]

2. Please describe the issue you observed:

Stopped responding, process has ended. Nothing special in the logs. Here's the last bit of the info and warning logs:

I161207 08:54:29.366580 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 28 MiB/65 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 1000.21cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (4x)
I161207 08:54:39.366627 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 27 MiB/66 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 992.40cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (3x)
I161207 08:54:49.366463 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 25 MiB/68 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 929.42cgo/sec, 0.05/0.00 %(u/s)time, 0.00 %gc (3x)
I161207 08:54:59.366518 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 29 MiB/65 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 1158.09cgo/sec, 0.06/0.00 %(u/s)time, 0.00 %gc (3x)
I161207 08:55:09.324103 57 gossip/gossip.go:435 [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
I161207 08:55:09.366643 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 60 MiB/38 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 898.79cgo/sec, 0.05/0.00 %(u/s)time, 0.00 %gc (2x)
I161207 08:55:19.465146 60 server/status/runtime.go:228 runtime stats: 6.0 GiB RSS, 69 goroutines, 3.6 GiB/20 MiB/3.8 GiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 7333.36cgo/sec, 0.46/0.26 %(u/s)time, 0.00 %gc (12x)

and the entirety of the most recent warning log:

W161206 21:45:08.716350 1 util/log/clog.go:1002 [config] file created at: 2016/12/06 21:45:08
W161206 21:45:08.716350 1 util/log/clog.go:1002 [config] running on machine: sonicfe
W161206 21:45:08.716350 1 util/log/clog.go:1002 [config] binary: CockroachDB beta-20161201 (linux amd64, built 2016/12/01 18:32:34, go1.7.3)
W161206 21:45:08.716350 1 util/log/clog.go:1002 [config] arguments: [cockroach start --store=/home/sonic/cockroach-data/ --http-port 8280]
W161206 21:45:08.716350 1 util/log/clog.go:1002 line format: [IWEF]yymmdd hh:mm:ss.uuuuuu goid file:line msg
W161206 21:45:08.716348 1 server/server.go:154 [n?] running in insecure mode, this is strongly discouraged. See --insecure.
W161206 21:45:08.716844 1 gossip/gossip.go:1124 [n?] no resolvers found; use --join to specify a connected node
W161206 21:45:09.293588 1 storage/store.go:817 [n1] storeMu: mutex held by github.com/cockroachdb/cockroach/pkg/storage.(*Store).Start for 302.927783ms (>100ms):
goroutine 1 [running]:
runtime/debug.Stack(0x1e7f6c8, 0x1e7f708, 0x3b)
/usr/local/go/src/runtime/debug/stack.go:24 +0x79
github.com/cockroachdb/cockroach/pkg/util/syncutil.ThresholdLogger.func1(0x120e4fa7)
/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:67 +0xe1
github.com/cockroachdb/cockroach/pkg/util/syncutil.(*TimedMutex).Unlock(0xc4203589f0)
/go/src/github.com/cockroachdb/cockroach/pkg/util/syncutil/timedmutex.go:97 +0xb6
github.com/cockroachdb/cockroach/pkg/storage.(*Store).Start(0xc420358700, 0x2533aa0, 0xc4203dc7e0, 0xc42016d4d0, 0xc420360c60, 0x1)
/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:1098 +0x4d1
github.com/cockroachdb/cockroach/pkg/server.(*Node).initStores(0xc420158000, 0x2533aa0, 0xc4203dc7e0, 0xc4203ac710, 0x1, 0x1, 0xc42016d4d0, 0x0, 0x0, 0x2)
/go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:417 +0x209
github.com/cockroachdb/cockroach/pkg/server.(*Node).start(0xc420158000, 0x2533aa0, 0xc4203dc7e0, 0x2525e60, 0xc420302380, 0xc4203ac710, 0x1, 0x1, 0x0, 0x0, ...)
/go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:339 +0x11d
github.com/cockroachdb/cockroach/pkg/server.(*Server).Start(0xc4201ee400, 0x2533aa0, 0xc4203dc7e0, 0xc4201ceec0, 0x1)
/go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:600 +0xd03
github.com/cockroachdb/cockroach/pkg/cli.runStart(0x250f500, 0xc420282cc0, 0x0, 0x3, 0x0, 0xc4202a8dc0)
/go/src/github.com/cockroachdb/cockroach/pkg/cli/start.go:343 +0x8fa
github.com/cockroachdb/cockroach/pkg/cli.maybeDecorateGRPCError.func1(0x250f500, 0xc420282cc0, 0x0, 0x3, 0x0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/cli/error.go:30 +0x5a
github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra.(*Command).execute(0x250f500, 0xc420282c30, 0x3, 0x3, 0x250f500, 0xc420282c30)
/go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:632 +0x23e
github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0x250b100, 0xc4200101a0, 0xb9d07b536048cad2, 0xc4200101d8)
/go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:722 +0x367
github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra.(*Command).Execute(0x250b100, 0xc4200101c0, 0xb9d07b536048cad2)
/go/src/github.com/cockroachdb/cockroach/vendor/github.com/spf13/cobra/command.go:681 +0x2b
github.com/cockroachdb/cockroach/pkg/cli.Run(0xc42000c0b0, 0x4, 0x4, 0x0, 0x0)
/go/src/github.com/cockroachdb/cockroach/pkg/cli/cli.go:95 +0x6d
main.main()
/go/src/github.com/cockroachdb/cockroach/main.go:35 +0xe1

• What did you do?

Only thing I can think of is that I started the process interactively not from a process manager, but I stopped running it under supervisord because it was crashing so often (the previous beta from Nov) that I wanted to know whenever it went down.

But I am pretty certain I started it with --background (regardless of what the [config] lines say, and that that terminal is still active.

• What did you expect to see?

Even if it died because the shell that started it died, I expect to see SOMETHING in the logs, but as I said, I don't think that happened.

• What did you see instead?

No evidence of why the process ended.

[a-robinson]

Hmm. Can you check whether it got OOM-killed? The process must have been SIGKILL'ed or else there would be a bunch of shutdown-related messages at the end of the log.

[benmargolin]

Sure, where would I find that? I don't see anything in /var/log/kern.log, or anything in syslog or daemon.log that seems relevant (grepped it for 'cockroach').
This is on ubuntu (Google Compute Engine instance) - Linux sonicfe 3.16.0-4-amd64 #1 SMP Debian 3.16.36-1+deb8u2 (2016-10-19) x86_64 GNU/Linux

(also checked /var/log/messages, sorry)

[knz]

What did the dmesg command say?

[benmargolin]

Also no smoking gun (to my eyes) in dmesg. Here's the last bit of that:

[ 4.652247] random: nonblocking pool is initialized
[2427185.155819] hrtimer: interrupt took 143132907 ns
[2574647.583830] [sched_delayed] sched: RT throttling activated

[benmargolin]

BTW there are times I've done 'top' and seen cockroach taking 50% under %MEM, which seems... strange? I thought it throttles itself to 25% (or is that just its internal caches)?

In my app I am possibly 'abusing' things btw, I do store large blobs (column type BYTES), between say 30k and 1MB.

Oh, it just crashed again while I was looking around the machine and I got a stack dump to stderr (I guess?). I'm attaching it here! It does say OOM so... good info at least..
cockroach_crash_12071055.txt

[a-robinson]

It limits its RocksDB cache size to 25% of the machine's physical memory by default, but other parts of the system use memory as well (e.g. we allow SQL queries to use up to 25% of the system memory as well). There are more details about cockroach's memory usage in https://www.cockroachlabs.com/blog/memory-usage-cockroachdb/

What kind of SQL queries are you throwing at it / how much data are you storing?

@knz, does anything stand out to you?

[knz]

I see in this panic a table scan -- can you tell us which query was running when this failed?

[benmargolin]

Unfortunately I don't know for certain, there are multiple clients and I don't have fine-grained logging. I think the most likely culprit was one of the following (possibly several of these queries in flight):
SELECT data FROM messages WHERE id= -- this is a select on a BYTES column. That table has FAMILY "primary" (id, rowid) (honestly 'id' should be PK). There are <2k records in this table.

Here's the table def:
CREATE TABLE messages (␤ |
| | id STRING NOT NULL,␤ |
| | sender STRING(40) NOT NULL,␤ |
| | recipient STRING(80) NOT NULL,␤ |
| | data BYTES NULL,␤ |
| | created TIMESTAMP NOT NULL DEFAULT "CURRENT_TIMESTAMP"(),␤ |
| | transcription STRING NULL,␤ |
| | is_group BOOL NOT NULL DEFAULT false,␤ |
| | fetches INT NOT NULL DEFAULT 0,␤ |
| | time_heard TIMESTAMP NULL,␤ |
| | deleted BOOL NOT NULL DEFAULT false,␤ |
| | FAMILY "primary" (id, rowid),␤ |
| | FAMILY fam_1_sender_recipient_created_is_group (sender, recipient, created, is_group, fetches, time_heard, deleted),␤ |
| | FAMILY fam_2_data (data),␤ |
| | FAMILY fam_3_transcription (transcription)␤ |
| | )

it might also have been a query like this:

UPDATE stats SET value=value+$1 WHERE key=$2 ($1=1, $2=some string)

[benmargolin]

BTW it did it again, similar stack trace (attaching for completeness).
cockroach_crash_12071126.txt

[knz]

In both cases the query is a plain SELECT.
Could you track this further by starting your server with the additional flag --vmodule=executor=2, this will log the queries being executed. If there is another crash we can find the query just before the stack trace this way.

[benmargolin]

"If" there is another crash, I like your optimism, ha :) Anyhow, restarted with that flag.

Latest crash has a slightly different stack signature. See attached for last bit of INFO log & dump
cockroach_crash_12071330.txt
.

[benmargolin]

BTW I just saw this in top (note mem usage by cockroach)

%Cpu(s):  0.6 us,  2.3 sy,  0.0 ni,  2.6 id, 94.4 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem:   7679804 total,  7547980 used,   131824 free,       60 buffers
KiB Swap:        0 total,        0 used,        0 free.    64140 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                          
 8680 margolin  20   0 7301336 6.720g      0 S   4.6 91.8   1:30.38 cockroach

cockroach_dump_highmemusage.txt

amazingly, it did NOT crash, although I got a dump of the traces, attached. (Also mixed in with the trace is some of the INFO log, I was tail -f'ing it in the same window)

[benmargolin]

Just an update: it did crash a few more times, with nothing obvious in the logs, and I didn't catch stacktraces. What I ended up doing was 1. no longer storing byte blobs as one of the fields and 2. reindexing the same table such that rowid wasn't involved (since there was a better field to index off, but note that the blob field was never in an index). Since then I haven't had any crashes, probably due to it not trying to do anything with those blobs, but I don't know for certain, obviously (and if it was simply a scan, it doesn't seem like that would have fixed it). So for now I'm ok with closing this bug as I won't be able to provide additional details, but feel free to keep it open if you think it's going to help you / has enough info for further debugging. Thanks for the engagement throughout, though, I really appreciate it!

[knz]

Huh now you're saying this I actually have an idea -- how big were these blobs exactly?

(I know we're not doing size checks in that part of the code yet, so you may have ran into an edge case.)

[benmargolin]

Sorry for slow response -- size varied, from say 32k to 1MB, averaging around 150k.

[knz]

Another question about this: I see there were several requests in-flight. How many active connections were there on the crashing node?

[knz]

FWIW the crash is in our RocksDB interface (that's what MVCCIterate is right?):

fatal error: runtime: out of memory

runtime stack:
runtime.throw(0x1993729, 0x16)
	/usr/local/go/src/runtime/panic.go:566 +0x95
runtime.sysMap(0xc582320000, 0x100000, 0x0, 0x2a42898)
	/usr/local/go/src/runtime/mem_linux.go:219 +0x1d0
runtime.(*mheap).sysAlloc(0x29faa60, 0x100000, 0x1a)
	/usr/local/go/src/runtime/malloc.go:407 +0x37a
runtime.(*mheap).grow(0x29faa60, 0x15, 0x0)
	/usr/local/go/src/runtime/mheap.go:726 +0x62
runtime.(*mheap).allocSpanLocked(0x29faa60, 0x15, 0x4000)
	/usr/local/go/src/runtime/mheap.go:630 +0x4f2
runtime.(*mheap).alloc_m(0x29faa60, 0x15, 0x7f0100000000, 0xf)
	/usr/local/go/src/runtime/mheap.go:515 +0xe0
runtime.(*mheap).alloc.func1()
	/usr/local/go/src/runtime/mheap.go:579 +0x4b
runtime.systemstack(0x7f65ff5fdb98)
	/usr/local/go/src/runtime/asm_amd64.s:314 +0xab
runtime.(*mheap).alloc(0x29faa60, 0x15, 0x10100000000, 0xc551c39f18)
	/usr/local/go/src/runtime/mheap.go:580 +0x73
runtime.largeAlloc(0x29ab3, 0x7f65ff5fdc01, 0x659f9a)
	/usr/local/go/src/runtime/malloc.go:774 +0x93
runtime.mallocgc.func1()
	/usr/local/go/src/runtime/malloc.go:669 +0x3e
runtime.systemstack(0xc42001b500)
	/usr/local/go/src/runtime/asm_amd64.s:298 +0x79
runtime.mstart()
	/usr/local/go/src/runtime/proc.go:1079

goroutine 236114 [running]:
runtime.systemstack_switch()
	/usr/local/go/src/runtime/asm_amd64.s:252 fp=0xc551c39e28 sp=0xc551c39e20
runtime.mallocgc(0x29ab3, 0x1796700, 0x1, 0x0)
	/usr/local/go/src/runtime/malloc.go:670 +0x903 fp=0xc551c39ec8 sp=0xc551c39e28
runtime.makeslice(0x1796700, 0x0, 0x29ab3, 0x0, 0x0, 0x1)
	/usr/local/go/src/runtime/slice.go:57 +0x7b fp=0xc551c39f20 sp=0xc551c39ec8
github.com/cockroachdb/cockroach/pkg/util/bufalloc.ByteAllocator.Alloc(0xc582304000, 0xa2, 0x4000, 0x29ab3, 0x0, 0xc582304000, 0x0, 0x4000, 0xc582304094, 0xd, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/bufalloc/byte_allocator.go:49 +0x86 fp=0xc551c39f60 sp=0xc551c39f20
github.com/cockroachdb/cockroach/pkg/util/bufalloc.ByteAllocator.Copy(0xc582304000, 0xa2, 0x4000, 0x7f65c1835245, 0x29ab3, 0x29ab3, 0x0, 0x0, 0x1, 0x148e16af3a18ffa7, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/bufalloc/byte_allocator.go:62 +0x66 fp=0xc551c39fe0 sp=0xc551c39f60
github.com/cockroachdb/cockroach/pkg/storage/engine.MVCCIterate(0x2533aa0, 0xc494160330, 0x25382c0, 0xc420382b90, 0xc4424e4820, 0xb, 0x10, 0xc4424e4850, 0xb, 0x10, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/mvcc.go:1649 +0x12ad fp=0xc551c3a498 sp=0xc551c39fe0
github.com/cockroachdb/cockroach/pkg/storage/engine.mvccScanInternal(0x2533aa0, 0xc494160330, 0x25382c0, 0xc420382b90, 0xc4424e4820, 0xb, 0x10, 0xc4424e4850, 0xb, 0x10, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/mvcc.go:1511 +0x321 fp=0xc551c3a5d0 sp=0xc551c3a498
github.com/cockroachdb/cockroach/pkg/storage/engine.MVCCScan(0x2533aa0, 0xc494160330, 0x25382c0, 0xc420382b90, 0xc4424e4820, 0xb, 0x10, 0xc4424e4850, 0xb, 0x10, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/mvcc.go:1533 +0xf8 fp=0xc551c3a6a8 sp=0xc551c3a5d0
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).Scan(0xc42075f200, 0x2533aa0, 0xc494160330, 0x7f660dad98b8, 0xc420382b90, 0x148e16af3a18ffa7, 0x1, 0x100000001, 0x1, 0x5c, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_command.go:375 +0x19e fp=0xc551c3ac60 sp=0xc551c3a6a8
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).executeCmd(0xc42075f200, 0x2533aa0, 0xc494160330, 0x0, 0x0, 0x0, 0x7f660dad98b8, 0xc420382b90, 0x0, 0x148e16af3a18ffa7, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica_command.go:119 +0x1ed0 fp=0xc551c3b9c8 sp=0xc551c3ac60
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).executeBatch(0xc42075f200, 0x2533aa0, 0xc494160330, 0x0, 0x0, 0x7f660dad98b8, 0xc420382b90, 0x0, 0x148e16af3a18ffa7, 0x1, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3867 +0x426 fp=0xc551c3cb18 sp=0xc551c3b9c8
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).addReadOnlyCmd(0xc42075f200, 0x2533aa0, 0xc494160330, 0x148e16af3a18ffa7, 0x1, 0x100000001, 0x1, 0x5c, 0x0, 0xc4a96b8840, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:1678 +0x2cf fp=0xc551c3d088 sp=0xc551c3cb18
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).Send(0xc42075f200, 0x2533aa0, 0xc494160330, 0x148e16af3a18ffa7, 0x1, 0x100000001, 0x1, 0x5c, 0x0, 0xc4a96b8840, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:1195 +0x48f fp=0xc551c3d1e8 sp=0xc551c3d088
github.com/cockroachdb/cockroach/pkg/storage.(*Store).Send(0xc420436000, 0x2533aa0, 0xc4941601b0, 0x148e16af3a18ffa7, 0x1, 0x100000001, 0x1, 0x5c, 0x0, 0xc4a96b8840, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:2454 +0x75e fp=0xc551c3d8b0 sp=0xc551c3d1e8

@petermattis does this ring a bell?

[petermattis]

An out of memory error in RocksDB (or C++) usually indicates there was a memory leak on the Go side. That is, the allocation in C++ was the straw that broke the camel's back, but not the real cause of the leak.

If this leak/crash is reproducible, it would be useful to get Go memory profiles. Either set COCKROACH_MEMPROF_INTERVAL=10s or use go tool pprof http://<adminUI>/debug/heap.

Looking at the earlier messages on this issue, I see:

I161207 08:55:09.366643 60 server/status/runtime.go:228 runtime stats: 2.5 GiB RSS, 60 goroutines, 60 MiB/38 MiB/245 MiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 898.79cgo/sec, 0.05/0.00 %(u/s)time, 0.00 %gc (2x)
I161207 08:55:19.465146 60 server/status/runtime.go:228 runtime stats: 6.0 GiB RSS, 69 goroutines, 3.6 GiB/20 MiB/3.8 GiB GO alloc/idle/total, 1.8 GiB/2.4 GiB CGO alloc/total, 7333.36cgo/sec, 0.46/0.26 %(u/s)time, 0.00 %gc (12x)

Notice that over the course of 10s, GO alloc jumped from 245 MiB to 3.8 GiB. The question is what caused that.

If you use the COCKROACH_MEMPROF_INTERVAL env var, note that the profiles will be written to the log directory.

[benmargolin]

I moved the blobs out of the sql DB into a blob-specific store so I haven't seen this happen since. Probably won't be able to dupe from my end, sorry :(

[petermattis]

Seems like there is nothing more that can be investigated here.