InfluxDB starts for 2 hours #6250

undera · 2016-04-07T10:27:49Z

This is the continuation of the issue #5764 . The machine I use and database I use is the same.

I have upgraded influxdb to 0.12 from debian (0.12.0-1). Now the start takes slightly over 2 hours. 33% increase is not bad, but still unacceptable to have downtime of 2 hours just to start. My dream is to replace MySQL server with InfluxDB, because I see InfluxDB is better to store my timeline data. MySQL starts within several seconds (I will keep memory consumption comparison for separate thread).

Can we improve InfluxDB to beat MySQL? :) I have my feeling that the long startup (and memory consumption also) is the price of being "schemaless", but in fact there is a schema that is kept in the memory. Loading that schema at startup takes long time and a lot of RAM (for certain cases). I might be wrong with my assumptions, sorry for being overconfident.

I've looked into logs, seems there's pretty long shard loads happening, I've grepped from log:
tsm1] 2016/04/06 21:43:56 /var/lib/influxdb/data/Loadosophia/default/512 database index loaded in 11m2.839406822s
[tsm1] 2016/04/06 21:47:00 /var/lib/influxdb/data/Loadosophia/default/513 database index loaded in 14m7.359681031s
[tsm1] 2016/04/06 21:54:48 /var/lib/influxdb/data/Loadosophia/default/525 database index loaded in 21m12.196889089s
[[tsm1] 2016/04/06 22:11:10 /var/lib/influxdb/data/Loadosophia/default/524 database index loaded in 27m14.029874898s
[tsm1] 2016/04/06 22:45:11 /var/lib/influxdb/data/Loadosophia/default/523 database index loaded in 1h12m5.557480759s
[tsm1] 2016/04/06 23:41:10 /var/lib/influxdb/data/Loadosophia/default/527 database index loaded in 1h54m9.795156493s

Attaching full startup log.
influxd.20160407.txt

jwilder · 2016-04-20T04:18:34Z

Would you be able to run:

influx_inspect dumptsmdev /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm?

There is a lot of lock contention related to loading the meta data index still. I suspect you are hitting that.

undera · 2016-04-20T12:32:09Z

undera@undera-desktop:~$ influx_inspect dumptsmdev /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm
Error opening TSM files:  init: read tombstones: invalid argument
panic: runtime error: invalid memory address or nil pointer dereference
        panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x0 pc=0x518173]

goroutine 1 [running]:
github.com/influxdata/influxdb/tsdb/engine/tsm1.(*TSMReader).Close(0x0, 0x0, 0x0)
        /tmp/influxdb/src/github.com/influxdata/influxdb/tsdb/engine/tsm1/reader.go:262 +0xd3
github.com/influxdata/influxdb/tsdb/engine/tsm1.(*TSMReader).TimeRange(0x0, 0x27, 0x27)
        /tmp/influxdb/src/github.com/influxdata/influxdb/tsdb/engine/tsm1/reader.go:306 +0x5d
main.cmdDumpTsm1dev(0xc20800aea0)
        /tmp/influxdb/src/github.com/influxdata/influxdb/cmd/influx_inspect/tsm.go:481 +0x2c3
main.main()
        /tmp/influxdb/src/github.com/influxdata/influxdb/cmd/influx_inspect/main.go:115 +0xf82

undera@undera-desktop:~$ ls -la /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm
-rw-r--r-- 1 influxdb influxdb 139593214 Feb 16 10:08 /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm

jwilder · 2016-04-20T18:26:54Z

@undera Can you run ls -la /var/lib/influxdb/data/Loadosophia/default/527/? I've never seen that error before.

undera · 2016-04-20T18:35:51Z

undera@undera-desktop:~$ ls -la /var/lib/influxdb/data/Loadosophia/default/527/
total 136332
drwxr-xr-x   2 influxdb influxdb      4096 Feb 16 13:42 .
drwxr-xr-x 219 influxdb influxdb      4096 Feb 16 13:54 ..
-rw-------   1 influxdb influxdb         0 Feb 16 13:42 000000058-000000002.tombstone
-rw-r--r--   1 influxdb influxdb 139593214 Feb 16 10:08 000000058-000000002.tsm

jwilder · 2016-04-20T18:38:54Z

@undera Looks like a permissions issue. The file is owned by influxdb, but you might not be running influx_inspect as influxdb user. Try running it as influxdb user.

undera · 2016-04-20T19:24:23Z

Good to know. Probably error diagnostics could be improved to hint me the permissions issue.

Here's the output with sudo:

undera@undera-desktop:~$ sudo influx_inspect dumptsmdev /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm
[sudo] password for undera: 
Summary:
  File: /var/lib/influxdb/data/Loadosophia/default/527/000000058-000000002.tsm
  Time Range: 2015-03-23T00:00:00Z - 2015-03-29T23:59:59Z
  Duration: 167h59m59s   Series: 355019   File Size: 139593214

Statistics
  Blocks:
    Total: 407136 Size: 113188590 Min: 20 Max: 8426 Avg: 278
  Index:
    Total: 407136 Size: 26404611
  Points:
    Total: 73529019
  Encoding:
    Timestamp:  none: 0 (0%)    s8b: 192803 (47%)       rle: 214333 (52%) 
    Float:      none: 0 (0%)    gor: 41792 (10%) 
    Int:        none: 0 (0%)    s8b: 346613 (85%)       rle: 18731 (4%) 
  Compression:
    Per block: 1.54 bytes/point
    Total: 1.90 bytes/point

jwilder · 2016-04-20T19:33:47Z

@undera It shouldn't panic like that. That's a separate bug.

How many shards do you have in /var/lib/influxdb/data/Loadosophia/default/?

undera · 2016-04-20T19:37:13Z

I have 217 of subfolders there

aderumier · 2016-05-12T02:00:56Z

Hi,
I still have slow start time, even with 0.13-rc2.

https://gist.github.com/aderumier/63921e366ac3eae5cc73965075f04370

around 1h.
I have around 115GB datas on ssd (intel s3610). cpu was aroud 400% of 16cores when starting.

jwilder · 2016-05-12T20:05:09Z

@aderumier There are no specific fixes for this issue in 0.13. If you are able to test #6618, that would be helpful to know if it improves things.

aderumier · 2016-05-13T11:17:28Z

@jwilder I would like to help, but I have no idea how to build influxdb from source.Do you have a build somewhere ?

jwilder · 2016-05-13T21:05:52Z

@aderumier #6618 should be in tonights nightly. If you could test it out, that would be great.

daviesalex · 2016-05-16T21:01:22Z

Removing my previous comment; its very fast but thats because its only starting with a small fraction of our data. Same tombstone error reported above (and its not permissions!). Filed #6641 to track

cheribral · 2016-05-17T00:26:03Z

@jwilder I tried the latest nightly on one of our bigger databases with 11.5 million series, and it brought the startup time to 10 minutes from 34 minutes. There was still a lot of time though where most of the CPUs weren't doing anything, and the disk was quiet, so I'd assume there is still something getting hung up somewhere.

aderumier · 2016-05-17T04:06:02Z

@jwilder I have tried the latest nightly too, it's take around 10min now instead 1hour previously. As for cheribral, cpu and disk are quite low during the startup.

https://gist.github.com/aderumier/cafae2fbcf57c45254f79cc5f3e98ea0

jwilder · 2016-05-17T05:41:41Z

@aderumier @cheribral Could you run this after the server fully starts and attach the output to the issue?

curl -o block.txt "http://localhost:8086/debug/pprof/block?debug=1"

Also, when you restart can you monitor the process and see if you have a high amount of iowait CPU time?

aderumier · 2016-05-17T11:13:26Z

@jwilder : iowait was around 0,5% , cpu idle around 60% (of 16cores).

I can't restart it anymore, I have a tsm crash
`panic: interface conversion: tsm1.Value is *tsm1.IntegerValue, not *tsm1.FloatValue'

https://gist.github.com/aderumier/7be9507af94fb11423ce2ce6335b292d

I think it's related to #6641

jwilder · 2016-05-17T15:37:18Z

@aderumier I created a separate issue for the interface panic: #6652

The latest nightly reverts the commit that introduced that panic.

cheribral · 2016-05-18T00:38:43Z

@jwilder could this issue by any chance also cause "drop measurement" queries to take forever? I'm trying to clean up the database used to test this, and the queries have been running for hours blocking writes, and occassionally spitting out some lines about compaction in the log.

jwilder · 2016-05-18T01:02:57Z

drop measurement can be expensive if you are dropping a lot of series and/or have many shards.

If you grab these profiles, it might help identify the slowness.

curl -o block.txt "http://localhost:8086/debug/pprof/block?debug=1"
curl -o goroutine.txt "http://localhost:8086/debug/pprof/goroutine?debug=1"

aderumier · 2016-05-18T06:35:42Z

Ok, it's starting fine with last nightly (+-10min)
startup log

https://gist.github.com/aderumier/6c906efbf4dd8be9d75fcfae23ea46a1

debug output just after startup

block.txt
https://gist.github.com/aderumier/635e64959fda81c6c81f600209865065

goroutine.txt
https://gist.github.com/aderumier/0aca605cfd6e99d1c9bc400332c45884

jwilder · 2016-05-19T04:27:13Z

I have WIP branch that would be useful if someone could test on their dataset to see if it helps or not. This branch is still very experimental so please do not test on your production servers.

The branch is: https://github.com/influxdata/influxdb/tree/jw-db-index. It should significantly reduce the database index lock contention at startup and make better use of available cores for loading shards.

aderumier · 2016-05-19T05:04:39Z

@jwilder, I have tested the jw-db-index branch,no improvement for me (15min startup)

around 60% idle cpu of 16 cores

https://gist.github.com/aderumier/fcd4311f4fc42aa2e82b87b4601c91ba

jwilder · 2016-05-19T05:15:24Z

@aderumier Thanks for testing it. Would you be able to grab the block and goroutine profile while it's running? Is there much iowait or sys time? Also, could you run influx_inspect dumptsmdev /var/lib/influxdb/data/telegraf/default/2/000003531-000000006.tsm and attach the output?

aderumier · 2016-05-19T14:07:54Z

@jwilder

iowait and sys time are around 0, I see only user cpu

dumptsmdev dump
https://gist.github.com/aderumier/bfc1250140ee740234e6c4b80efb2ec5

for block and goroutine profile, do you want it just after start, or during the start ?

jwilder · 2016-05-19T14:14:40Z

Block at the end. Goroutine somewhere in the middle of loading.

aderumier · 2016-05-19T14:27:42Z

I can't launch goroutine profile when loading, because port 8086 is not listening

aderumier · 2016-05-19T14:37:37Z

just after start:
goroutine.txt : https://gist.github.com/aderumier/4fe6ed205ae4511ff5897215f68749f3
block.txt : https://gist.github.com/aderumier/b6a4666de6ef7ccc19fa1c24bfbef900

jwilder · 2016-05-19T15:26:30Z

@aderumier A few things I can see:

The slowest file to load has 11387193 keys and 11540148 index entries. 11.3M keys is a lot and scanning is single-threaded so this is probably the biggest bottleneck for your dataset right now.
Unrelated to startup, but writing snapshots are probably taking a while due to sorting 11M keys. Looks like There is no need to sort keys for snapshot #6613 was created to try to fix that.

I'll take a look at the scanning, but you might want to see if you can reduce your series cardinality as well. If you don't need something as a tag, removing it will help future data.

aderumier · 2016-05-19T15:40:08Z

Do you known why my collectd database index are fast to load (around 30s),
vs telegraf database (7 - 13m) ?

database volume size: collectd : 74G , telegraf : 98G
(I don't known how to see number of keys in each database)

[store] 2016/05/19 06:46:35 /var/lib/influxdb/data/collectd/default/1 opened in 24.880605565s
[shard] 2016/05/19 06:46:44 /var/lib/influxdb/data/collectd/default/64 database index loaded in 25.140821417s
[store] 2016/05/19 06:46:44 /var/lib/influxdb/data/collectd/default/64 opened in 34.265438091s
[shard] 2016/05/19 06:46:47 /var/lib/influxdb/data/collectd/default/39 database index loaded in 35.460417614s
[store] 2016/05/19 06:46:47 /var/lib/influxdb/data/collectd/default/39 opened in 36.230742355s
[shard] 2016/05/19 06:46:48 /var/lib/influxdb/data/collectd/default/51 database index loaded in 36.598355259s
[store] 2016/05/19 06:46:48 /var/lib/influxdb/data/collectd/default/51 opened in 37.540704275s

[shard] 2016/05/19 06:50:32 /var/lib/influxdb/data/telegraf/default/66 database index loaded in 4m14.321419953s
[store] 2016/05/19 06:50:32 /var/lib/influxdb/data/telegraf/default/66 opened in 4m21.871790038s
[shard] 2016/05/19 06:53:31 /var/lib/influxdb/data/telegraf/default/53 database index loaded in 7m14.783794333s
[store] 2016/05/19 06:53:31 /var/lib/influxdb/data/telegraf/default/53 opened in 7m20.580999148s
[shard] 2016/05/19 06:56:40 /var/lib/influxdb/data/telegraf/default/41 database index loaded in 10m23.94684031s
[store] 2016/05/19 06:56:40 /var/lib/influxdb/data/telegraf/default/41 opened in 10m30.111645008s
[shard] 2016/05/19 07:00:09 /var/lib/influxdb/data/telegraf/default/2 database index loaded in 13m52.989010458s
[store] 2016/05/19 07:00:09 /var/lib/influxdb/data/telegraf/default/2 opened in 13m58.952826284s

jwilder · 2016-05-19T15:43:05Z

@aderumier Can you run influx_inspect dumptsmdev <path to collectd tsm file> on one the larger TSM files in /var/lib/influxdb/data/collectd/default/51?

aderumier · 2016-05-20T00:01:00Z

Summary:
File: /var/lib/influxdb/data/collectd/default/51/000003058-000000006.tsm
Time Range: 2016-05-15T00:41:40.015183Z - 2016-05-15T18:09:35.169648Z
Duration: 17h27m55.154465s Series: 220825 File Size: 2147705800

Statistics
Blocks:
Total: 440543 Size: 2115267309 Min: 30 Max: 12140 Avg: 4801
Index:
Total: 440543 Size: 32438478
Points:
Total: 420725151
Encoding:
Timestamp: none: 0 (0%) s8b: 440390 (99%) rle: 153 (0%)
Float: none: 0 (0%) gor: 440543 (100%)
Compression:
Per block: 5.03 bytes/point
Total: 5.10 bytes/point

so 220825 for collectd vs 11387193 Series for telegraf, so 50x more Series for telegraf.
But indeed, I monitor a lot more differents metrics with telegraf than collectd.

aderumier · 2016-05-20T01:16:35Z

Is it possible to limit the number of keys in tsm files ?

aderumier · 2016-05-20T06:44:14Z

I also notice that I have only 4 shards (each 7days)

:/var/lib/influxdb/data/telegraf/default# ls -lah
total 16K
drwx------ 6 influxdb influxdb 61 mai 16 02:00 .
drwx------ 3 influxdb influxdb 28 avril 28 17:24 ..
drwxr-xr-x 2 influxdb influxdb 4,0K mai 3 02:32 2
drwxr-xr-x 2 influxdb influxdb 4,0K mai 10 02:27 41
drwxr-xr-x 2 influxdb influxdb 4,0K mai 17 03:17 53
drwxr-xr-x 2 influxdb influxdb 4,0K mai 20 08:43 66

Is it possible to create more small shards to improve load parallelism ?

aderumier · 2016-05-20T07:02:13Z

I think that
ALTER RETENTION POLICY default ON telegraf DURATION INF REPLICATION 1 SHARD DURATION 1d

should do it ?

jwilder · 2016-05-31T16:27:18Z

As of #6743, this issue should be resolved. There is still more tuning and improvement to be made to startup, but the the hour long startup time in some cases should be resolved now.

jwilder added the area/tsm label Apr 20, 2016

jwilder added this to the 1.0.0 milestone Apr 28, 2016

jwilder mentioned this issue May 2, 2016

High memory usage 0.12.2 #6513

Closed

jwilder self-assigned this May 9, 2016

jwilder mentioned this issue May 12, 2016

Optimize shard index loading #6618

Merged

3 tasks

jwilder mentioned this issue May 18, 2016

atomic.AddUint32 in UUID generation causing global lock in HTTP handler #6658

Closed

cheribral mentioned this issue May 19, 2016

[0.13] drop measurement/series taking a very long time #6669

Closed

jwilder mentioned this issue May 27, 2016

Optimize series key parsing on startup #6743

Merged

3 tasks

jwilder closed this as completed May 31, 2016

jwilder mentioned this issue Aug 18, 2016

Add high cardinality requirements doc #7175

Closed

timhallinflux modified the milestones: 1.0.0, 1.0.0 beta Dec 20, 2016

InfluxDB starts for 2 hours #6250

InfluxDB starts for 2 hours #6250

Comments

undera commented Apr 7, 2016

jwilder commented Apr 20, 2016

undera commented Apr 20, 2016

jwilder commented Apr 20, 2016

undera commented Apr 20, 2016

jwilder commented Apr 20, 2016

undera commented Apr 20, 2016 • edited Loading

jwilder commented Apr 20, 2016

undera commented Apr 20, 2016

aderumier commented May 12, 2016

jwilder commented May 12, 2016

aderumier commented May 13, 2016

jwilder commented May 13, 2016

daviesalex commented May 16, 2016 • edited Loading

cheribral commented May 17, 2016

aderumier commented May 17, 2016

jwilder commented May 17, 2016

aderumier commented May 17, 2016 • edited Loading

jwilder commented May 17, 2016

cheribral commented May 18, 2016

jwilder commented May 18, 2016

aderumier commented May 18, 2016 • edited Loading

jwilder commented May 19, 2016

aderumier commented May 19, 2016

jwilder commented May 19, 2016

aderumier commented May 19, 2016

jwilder commented May 19, 2016

aderumier commented May 19, 2016

aderumier commented May 19, 2016

jwilder commented May 19, 2016

aderumier commented May 19, 2016

jwilder commented May 19, 2016

aderumier commented May 20, 2016

aderumier commented May 20, 2016 • edited Loading

aderumier commented May 20, 2016

aderumier commented May 20, 2016

jwilder commented May 31, 2016

undera commented Apr 20, 2016 •

edited

Loading

daviesalex commented May 16, 2016 •

edited

Loading

aderumier commented May 17, 2016 •

edited

Loading

aderumier commented May 18, 2016 •

edited

Loading

aderumier commented May 20, 2016 •

edited

Loading