influxdata / influxdata/influxdb
[1.7.9] High memory uses often killed due to OOM. Then timeout on writes, potentially due to high memory usage. Pretty much unusable.
- Dominant language
- Rust
- Stars
- 31.7k
- Forks
- 3.7k
- Avg merge
- 13h 37m
- Merged PRs (30d)
- 8
Description
__Steps to reproduce:__
List the minimal actions needed to reproduce the behavior.
1. Issue writes through a CPP client which basically uses writev call.
2. Using tsi1 index.
__Expected behavior:__
Low memory usage and no timeouts. Infrequent timeouts already handling through backoff.
__Actual behavior:__
High memory usage(7.6GB/8GB) followed by timeouts and then so damn slow that it makes me wait for more than half an hour for a 5 minute execution time. However, at the end it does come back to around 2 GBs.
__Environment info:__
* System info: Run `uname -srm` and copy the output here
Linux 4.4.0-142-generic x86_64
* InfluxDB version: Run `influxd version` and copy the output here
InfluxDB v1.7.9 (git: 1.7 23bc63d43a8dc05f53afa46e3526ebb5578f3d88)
* Other relevant environment details: Container runtime, disk info, etc
Only application running on a VM. 8 GM RAM allocation with 4 CPUs. ESXi is not loaded either.
__Config:__
Copy any non-default config values here or attach the full config as a gist or file.
Only thing I changed is index from inmem to tsi1. Rest are defaults.
__Logs:__
Include snippet of errors in log.
```
Nov 11 15:04:09 ub influxd[12959]: ts=2019-11-11T20:04:09.223591Z lvl=info msg="Cache snapshot (end)" log_id=0J2~r7M0000 engine=tsm1 trace_id=0J30uDEG000 op_n
ame=tsm1_cache_snapshot op_event=end op_elapsed=6733.914ms
Nov 11 15:04:12 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:01 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 67987233-04be-
11ea-8188-000c292620c0 10780042
Nov 11 15:04:12 ub influxd[12959]: ts=2019-11-11T20:04:12.437295Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:20 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:01 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 204 0 "-" "-" 67c1877f-04be-1
1ea-8189-000c292620c0 18080219
Nov 11 15:04:27 ub influxd[12959]: ts=2019-11-11T20:04:27.909117Z lvl=info msg="Cache snapshot (start)" log_id=0J2~r7M0000 engine=tsm1 trace_id=0J30vlXG000 op
_name=tsm1_cache_snapshot op_event=start
Nov 11 15:04:29 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:10 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 6d0ed13b-04be-
11ea-818a-000c292620c0 19034349
Nov 11 15:04:29 ub influxd[12959]: ts=2019-11-11T20:04:29.855898Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:30 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:11 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 6d3d943e-04be-
11ea-818b-000c292620c0 19423632
Nov 11 15:04:30 ub influxd[12959]: ts=2019-11-11T20:04:30.551596Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:34 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:14 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 6f783cd0-04be-
11ea-818c-000c292620c0 19972154
Nov 11 15:04:34 ub influxd[12959]: ts=2019-11-11T20:04:34.840122Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:38 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:20 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 72ba2909-04be-
11ea-818d-000c292620c0 18158716
Nov 11 15:04:38 ub influxd[12959]: ts=2019-11-11T20:04:38.491763Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:46 ub influxd[12959]: ts=2019-11-11T20:04:46.144027Z lvl=info msg="Snapshot for path written" log_id=0J2~r7M0000 engine=tsm1 trace_id=0J30vlXG000
op_name=tsm1_cache_snapshot path=/var/lib/influxdb/data/demo_new/autogen/31 duration=18234.938ms
Nov 11 15:04:46 ub influxd[12959]: ts=2019-11-11T20:04:46.144947Z lvl=info msg="Cache snapshot (end)" log_id=0J2~r7M0000 engine=tsm1 trace_id=0J30vlXG000 op_n
ame=tsm1_cache_snapshot op_event=end op_elapsed=18235.851ms
Nov 11 15:04:55 ub influxd[12959]: [httpd] 70.0.76.195 - - [11/Nov/2019:15:04:39 -0500] "POST /write?db=demo_new&u=&p= HTTP/1.1" 500 20 "-" "-" 7e1783c9-04be-
11ea-818e-000c292620c0 16037474
Nov 11 15:04:55 ub influxd[12959]: ts=2019-11-11T20:04:55.437408Z lvl=error msg="[500] - \"timeout\"" log_id=0J2~r7M0000 service=httpd
Nov 11 15:04:59 ub influxd[12959]: ts=2019-11-11T20:04:59.256131Z lvl=info msg="Cache snapshot (start)" log_id=0J2~r7M0000 engine=tsm1 trace_id=0J30xfz0000 op
_name=tsm1_cache_snapshot op_event=start
```
__Performance:__
Generate profiles with the following commands for bugs related to performance, locking, out of memory (OOM), etc.
```sh
# Commands should be run when the bug is actively.
# Note: This command will run for at least 30 seconds.
curl -o profiles.tar.gz "http://localhost:8086/debug/pprof/all?cpu=true"
curl -o vars.txt "http://localhost:8086/debug/vars"
iostat -xd 1 30 > iostat.txt
# Attach the `profiles.tar.gz`, `vars.txt`, and `iostat.txt` output files.
```
[iostat.txt](https://github.com/influxdata/influxdb/files/3833103/iostat.txt)
[profiles.tar.gz](https://github.com/influxdata/influxdb/files/3833104/profiles.tar.gz)
[vars.txt](https://github.com/influxdata/influxdb/files/3833105/vars.txt)
Contributor guide
Research direction
Start by reproducing writes through the C++ client with the tsi1 index, while collecting profiles.tar.gz, vars.txt, and iostat.txt using the listed /debug/pprof/all and /debug/vars commands. Inspect the /write timeout and tsm1 cache snapshot logs to identify the memory and timeout behavior; done means writes no longer cause excessive memory use or repeated timeouts under the reported setup.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- cpp
- Domain
- databases
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100