[0.10.0rc1] panic in tsm1.Values.Deduplicate

[fffw]

Not sure if it's fixed on newer version because it didn't recur after I upgraded to 0.10.1, but might worth to have a quick check. I didn't find relevant previous issue.

panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x38 pc=0x7ffdc1]

goroutine 671991 [running]:
github.com/influxdb/influxdb/tsdb/engine/tsm1.Values.Deduplicate(0xc2c56ba000, 0x20054b, 0x20054b, 0x0, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/encoding.go:207 +0xf1
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Cache).merged(0xc25f12e460, 0xc2422e2690, 0x2c, 0x0, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/cache.go:280 +0x6f5
github.com/influxdb/influxdb/tsdb/engine/tsm1.func·002(0x0, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/cache.go:216 +0x8a
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Cache).Values(0xc25f12e460, 0xc2422e2690, 0x2c, 0x0, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/cache.go:217 +0x178
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*tx).Cursor(0xc2595e7880, 0xc2186e3c50, 0x21, 0xc23d2fa260, 0x1, 0x1, 0xc213a0dac0, 0xc23d2fa201, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/engine.go:645 +0x147
github.com/influxdb/influxdb/tsdb.(*AggregateMapper).openMeasurement(0xc24b8ad950, 0xc20810fc00, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/aggregate.go:690 +0x551
github.com/influxdb/influxdb/tsdb.(*AggregateMapper).Open(0xc24b8ad950, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/aggregate.go:646 +0x6fb
github.com/influxdb/influxdb/tsdb.(*AggregateExecutor).openMappers(0xc24cfc0100, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/aggregate.go:205 +0x9b
github.com/influxdb/influxdb/tsdb.(*AggregateExecutor).execute(0xc24cfc0100, 0xc2a24eb4a0, 0xc2a24eb3e0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/aggregate.go:70 +0x1ab
created by github.com/influxdb/influxdb/tsdb.(*AggregateExecutor).Execute
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/aggregate.go:48 +0x64

[jonseymour]

@fffw I haven't seen a report with that exact symptom. Did it happen more than once?

I did some work on a thread safety fix (#5701) that might explain the root cause of this issue since there were circumstances where a values slice servicing a query could be subject to unsynchronized updates from the compactor. It is just possible that issue might have resulted in memory being returned to the heap while it was still being accessed by a query and that could cause a symptom like the one you have reported.

This fix is in master but isn't in 0.10.1 so there is a possibility that this issue could occur again.

Having said that, though, I don't think I have seen this particular stack trace before, so it could be a different issue.

[fffw]

I've seen 3 occurrences before upgraded to 0.10.1, so it could possibly recur. Oh 0.10.1 hasn't come up for 24 hours so it's too early to say if it will recur. I'll comment once that happens.

2016/02/26 17:37:56
2016/02/27 00:19:32
2016/02/28 03:36:47

From logs, the panic always followed below CQ (I turned off HTTP log so I don't know if there're writes in between), so I'll not be surprised if it's a thread safety issue.

[query] 2016/02/26 17:37:56 SELECT count(service) AS requests, min(service) AS resp_min, mean(service) AS resp_mean, percentile(service, 95.000) AS resp_95_percent, max(service) AS resp_max INTO heroku."1_year"."1s_router" FROM heroku."default".router WHERE time >= '2016-02-26T22:17:19Z' AND time < '2016-02-26T22:17:20Z' GROUP BY time(1s), app, status fill(none)

[jonseymour]

Was there any evidence of TSM compaction activity at around the time of the crash? e.g. a tsm.tmp in a subdirectory of data/ or some entries in the log file. These .tsm.tmp files will get cleaned up on restart, so you need to check the directory when the server is down.

[fffw]

Thanks @jonseymour ! No such entry shown in the log file. I'll check the .tsm.tmp files if it crashes the next time.

[jonseymour]

@fffw - would you happen to have the full stack trace of one of these events available? If so, I can probably tell from that whether the issue I was concerned about was a factor. Also, if you are in a position to build your own version of influx, I am happy to back port the thread safety fix onto the 0.10.1 maintenance branch, if you like.

[fffw]

@jonseymour Sent full trace to your gmail. Unfortunately I don't have a chance to build manually ATM.

[jonseymour]

@fffw - the existence of this stack trace is highly consistent with an occurrence of the thread safety issue I fixed with #5701. I am happy to back port the fix onto 0.10.1 so that if influxdata decide to push a 0.10.2 it can go in there. If you can tell me what platform you are running on, I am happy to build a binary influxd for that platform. Of course, this would be completely unsupported in anything other than 'a buy me a beer next time you are in Sydney' sense :-)

goroutine 612868 [runnable]:
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Values).Less(0xc23c481be0, 0x8204, 0x84f9, 0x8d00)
        <autogenerated>:19
sort.doPivot(0x7f0741ed4cb8, 0xc23c481be0, 0x8204, 0x99a6, 0x13, 0x8204)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:129 +0x434
sort.quickSort(0x7f0741ed4cb8, 0xc23c481be0, 0x8204, 0x99a6, 0x21)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:173 +0xa9
sort.quickSort(0x7f0741ed4cb8, 0xc23c481be0, 0x0, 0x99a6, 0x24)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:180 +0x178
sort.quickSort(0x7f0741ed4cb8, 0xc23c481be0, 0x0, 0x23749, 0x25)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:177 +0x104
sort.quickSort(0x7f0741ed4cb8, 0xc23c481be0, 0x0, 0x6b3fa, 0x26)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:177 +0x104
sort.quickSort(0x7f0741ed4cb8, 0xc23c481be0, 0x0, 0xf365a, 0x27)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:177 +0x104
sort.Sort(0x7f0741ed4cb8, 0xc23c481be0)
        /root/.gvm/gos/go1.4.3/src/sort/sort.go:200 +0x7b
github.com/influxdb/influxdb/tsdb/engine/tsm1.Values.Deduplicate(0xc2b00ee000, 0xf365b, 0x12fc00, 0x0, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/encoding.go:215 +0x3e1
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*entry).deduplicate(0xc232ca1f40)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/cache.go:61 +0x4a
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Cache).Deduplicate(0xc236025450)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/cache.go:155 +0x76
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Engine).WriteSnapshot(0xc2a5bb0000, 0x0, 0x0)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/engine.go:417 +0xde
github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Engine).compactCache(0xc2a5bb0000)
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/engine.go:460 +0x10f
created by github.com/influxdb/influxdb/tsdb/engine/tsm1.(*Engine).Open
        /tmp/tmp.WXyOm7f2Na/src/github.com/influxdb/influxdb/tsdb/engine/tsm1/engine.go:135 +0x24e

[fffw]

You are so kind @jonseymour. It's running on 64bit Ubuntu but I probably want to stick on 0.10.1 and see if it will crash again ^_^

[jonseymour]

@fffw ok, so I have done the back port. I have no idea if it will be accepted into an 0.10.2 branch and there may be good reasons not to. But, the code is there if anyone wants to use it.

[fffw]

Bang! Now I hit the bug on 0.10.1. Let me see if I can build a linux64 binary tomorrow. @jonseymour if you by chance is very convenient to build one, that would be very thankful!

[jonseymour]

@fffw ok, you have options:

1. wait until I have created a fix-only variant of [0.10.x] Backport of cache related changes to 0.10.x #5858 which it looks might be accepted into 0.10.x
2. take the actual version I am running production myself (https://github.com/jonseymour/influxdb/commits/stable) that also contains some other fixes and the cache statistics enhancements.

Advantage of #1 is that is closer to code that influxdata will actually support in forums, etc. If you take my version, you only get help from me :-)

[jonseymour]

@fffw the fixes have now been merged into the 0.10.0 branch, so I suspect you now have a 3rd option which is to wait some non-negative number of days for a 0.10.2 release.

[fffw]

@jonseymour Thank you for all the help and suggestions! I probably need to allocate more time to keep track of the progress in the future. I'll close this case if it doesn't recur for a few days after applying one of the options on my production environment.