nebula数据库负载异常

Les1ie · 2020 年10 月 27 日 02:19

基本信息

nebula 版本：nebula 7weeks ago的版本，具体的版本号没找到
部署方式：单机docker-compose

docker images
REPOSITORY                   TAG                 IMAGE ID            CREATED             SIZE
vesoft/nebula-console        nightly             c534e10aeb57        7 weeks ago         249MB
vesoft/nebula-metad          nightly             540e260c1431        7 weeks ago         288MB
vesoft/nebula-storaged       nightly             296b06c25991        7 weeks ago         288MB
vesoft/nebula-graphd         nightly             511f2adcfb7e        7 weeks ago         282MB

硬件信息
- 磁盘（SSD / HDD）： hdd 2T*5，lvm合并为一个逻辑磁盘
- CPU、内存信息：40C 189GB
出问题的 Space 的创建方式：执行 describe space xxx;

=============================================================================
| ID | Name        | Partition number | Replica Factor | Charset | Collate  |
=============================================================================
| 34 |  Topology | 100              | 1              | utf8    | utf8_bin |
-----------------------------------------------------------------------------
Got 1 rows (Time spent: 442.754/444.4 ms)

问题的具体描述

服务器负载异常

load average: 90.27, 93.43, 95.97

在 nebula-cli中执行show spaces类的系统命令可以正常执行，但是执行fetch prop类的查询命令会阻塞，最后返回查询失败

(user@nebula) [IP_Topology]> fetch prop on sometag 12324;
[ERROR (-8)]: Get tag props failed
Tue Oct 27 01:15:51 2020

分析发现 cpu空闲，内存一共189GB，已使用80GB，SWAP大小16G，占满，磁盘IO一直有读写

此处有疑问是为什么内存大量空闲但是不占用内存，而是要写入到swap中，推测是数据库想要将数据写入到swap，但是swap大小不足导致写入失败导致阻塞。但是swap是写到了硬盘上，读写速度太慢，请问有办法控制他写入swap的策略么，比如我希望尽量占用内存，当内存满之后再写swap。

另外目前是使用docker单机部署的，参数都是使用默认的设置，看了文档里面关于参数的描述，可能我们本机需要做参数的修改，请问有推荐的参数设置么？

$ vmstat

$ top

pandasheeps · 2020 年10 月 27 日 02:40

我觉得，你应该首先找出fetch 失败的原因。
可以看一下log，看看是什么原因导致的失败。

min.wu · 2020 年10 月 27 日 03:28

dstat 看下，如果你没做什么操作，怎么会swap那么高。
top按内存使用排序看下。
应该是环境问题。

另外为什么要用2个月前的测试版本，release版本也有啊。

Les1ie · 2020 年10 月 27 日 05:36

使用 nebula-python和数据库交互，python抛出 timeout

  File "/usr/local/lib/python3.8/site-packages/nebula/Client.py", line 117, in execute_query
    raise ExecutionException("Execute `{}' failed: {}".format(statement, x))
 nebula.Common.ExecutionException: Execute `GO FROM 217 OVER someedge YIELD $$.sometag.name' failed: Socket read failed: timed out
 Traceback (most recent call last):
   File "/usr/local/lib/python3.8/site-packages/thrift/transport/TSocket.py", line 298, in read
     buff = self.handle.recv(sz)
 socket.timeout: timed out

查看日志可以看到里面有Timed Out的异常

graphd的日志

$ tail  graph/nebula-graphd.INFO 
I1027 03:27:28.835041    94 UseExecutor.cpp:48] Graph space switched to `TEST', space id: 34
I1027 03:27:49.888263    94 GraphService.cpp:50] Authenticating user user from 10.10.10.131:58192
I1027 03:27:52.192646    78 GraphService.cpp:50] Authenticating user user from 10.10.10.131:58196
I1027 03:27:52.194272    78 UseExecutor.cpp:48] Graph space switched to `TEST', space id: 34
E1027 03:28:29.368170    16 StorageClient.inl:123] Request to [172.28.2.2:44500] failed: N6apache6thrift9transport19TTransportExceptionE: Timed Out
E1027 03:28:29.368497    16 StorageClient.inl:123] Request to [172.28.2.3:44500] failed: N6apache6thrift9transport19TTransportExceptionE: Timed Out
E1027 03:28:29.368639    16 StorageClient.inl:123] Request to [172.28.2.1:44500] failed: N6apache6thrift9transport19TTransportExceptionE: Timed Out
E1027 03:28:29.368840    81 ExecutionPlan.cpp:80] Execute failed: Get dest props failed
E1027 03:28:52.204252    22 StorageClient.inl:123] Request to [172.28.2.1:44500] failed: N6apache6thrift9transport19TTransportExceptionE: Timed Out
E1027 03:28:52.204530    78 ExecutionPlan.cpp:80] Execute failed: Get neighbors failed

其中一个storage的日志

$ tail  storage0/nebula-storaged.INFO -n 20
I1027 03:30:22.826171    70 CompactionFilter.h:67] Do default minor compaction!
I1027 03:30:45.781060    70 EventListner.h:33] Rocksdb compact column family: default because of 1, status: OK, compacted 15 files into 8, base level is 0, output level is 1
I1027 03:30:46.804128    70 EventListner.h:23] Rocksdb compact column family: default because of 2, status: OK, compacted 5 files into 0, base level is 1, output level is 2
I1027 03:30:46.804448    70 CompactionFilter.h:67] Do default minor compaction!
I1027 03:30:47.997128    26 InMemoryLogBuffer.h:27] [Port: 44501, Space: 63, Part: 84] InMemoryLogBuffer dtor, firstLogId 3639252
I1027 03:30:48.001283    26 InMemoryLogBuffer.h:23] [Port: 44501, Space: 63, Part: 84] InMemoryLogBuffer ctor, firstLogId 3661806
I1027 03:30:49.721815    64 SlowOpTracker.h:33] [Port: 44501, Space: 59, Part: 9] , total time:207ms, Write WAL, total 2
I1027 03:30:49.722144    66 SlowOpTracker.h:33] [Port: 44501, Space: 59, Part: 45] , total time:207ms, Write WAL, total 2
I1027 03:30:49.723392    67 SlowOpTracker.h:33] [Port: 44501, Space: 59, Part: 57] , total time:209ms, Write WAL, total 2
I1027 03:30:50.502573    14 SlowOpTracker.h:33] [Port: 44501, Space: 51, Part: 45] , total time:180ms, Total commit: 1
I1027 03:30:52.897030    42 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 60] , total time:203ms, Write WAL, total 2
I1027 03:30:53.362690    42 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 24] , total time:431ms, Write WAL, total 2
I1027 03:30:53.804636    41 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 63] , total time:69ms, Write WAL, total 2
I1027 03:30:53.804633    24 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 57] , total time:70ms, Write WAL, total 2
I1027 03:30:53.804641    21 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 72] , total time:69ms, Write WAL, total 2
I1027 03:30:53.804642    22 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 51] , total time:70ms, Write WAL, total 2
I1027 03:30:53.804649    26 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 66] , total time:71ms, Write WAL, total 2
I1027 03:30:53.804652    39 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 48] , total time:71ms, Write WAL, total 2
I1027 03:30:53.804726    37 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 69] , total time:70ms, Write WAL, total 2
I1027 03:30:53.804859    13 SlowOpTracker.h:33] [Port: 44501, Space: 63, Part: 45] , total time:71ms, Write WAL, total 2

Les1ie · 2020 年10 月 27 日 05:44

dstat 看下，如果你没做什么操作，怎么会swap那么高。

你好，看 dstat 的输出看起来是磁盘一直有读写机器的磁盘是HDD 2T*5 做的 lvm，可能比较容易到瓶颈。

dstat -cdngy
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read  writ| recv  send|  in   out | int   csw 
 26   3  64   6   0|9644k   22M|   0     0 | 911B   51k|  12k   38k
 17   5  74   3   0|8692k   61M|  18M   35M|   0     0 |  24k  185k
  4   4  90   3   0| 380k   26M|1476B  404B|   0     0 |  11k 2477 
 18   4  72   5   0|7948k   93M|  18M   36M|   0     0 |  21k  187k
  4   0  90   6   0|1184k   87M|2335k 4586k|   0     0 |4598    25k
 21   5  70   4   0|8452k   19M|  20M   39M|   0    24k|  22k  193k
  2   3  90   5   0| 444k   93M|1374B  358B|   0    36k|  11k 2970 
 19   5  73   4   0|9276k  107M|  22M   43M|   0     0 |  29k  211k
 23   5  69   4   0|  21M   39M|  22M   43M|   0     0 |  26k  210k
 17   5  76   3   0|  30M   63M|  14M   27M|   0     0 |  22k  134k
  4   3  90   4   0|4760k   68M|2226B  697B|   0     0 |  11k 2375 
 17   3  76   4   0|5236k   86M|  13M   26M|   0     0 |  22k  129

top按内存使用排序看下。

按内存和CPU排序的 top

另外为什么要用2个月前的测试版本，release版本也有啊。

两个月前部署的机器，考虑着部署方便直接就起了github提供的docker-compose模板，也没有调整参数就上了

Les1ie · 2020 年10 月 27 日 05:48

今早发了帖子之后把 swap 扩大到了 50G，操作之后负载在一直缓慢下降，但是 swap 的占用却没有多大变化，还是 15GB
最近十分钟内没有对数据库做读写操作，但是 graphd 负载较高

Les1ie · 2020 年10 月 27 日 05:53

$ show hosts

(user@nebula) [Topology]> show hosts;
==================================================================================================================================================================================================================================================================================
| Ip         | Port  | Status | Leader count | Leader distribution
  | Partition distribution                                                                                          |
==================================================================================================================================================================================================================================================================================
| 172.28.2.1 | 44500 | online | 198          | Topology: 33, Topology_Rich: 33, TEST_CCCC: 33, Topology_Dynamic: 33, TEST: 33, SOMEDB: 33
  | SOMEDB: 33, Topology: 33, Topology_Rich: 33, TEST: 33, Topology_Dynamic: 33, TEST_CCCC: 33       |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 172.28.2.2 | 44500 | online | 204          | Topology: 34, Topology_Rich: 34, TEST_CCCC: 34, Topology_Dynamic: 34, TEST: 34, SOMEDB: 34
  | SOMEDB: 34, Topology: 34, Topology_Rich: 34, TEST: 34, Topology_Dynamic: 34, TEST_CCCC: 34       |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 172.28.2.3 | 44500 | online | 198          | Topology: 33, Topology_Rich: 33, TEST_CCCC: 33, Topology_Dynamic: 33, TEST: 33, SOMEDB: 33
  | SOMEDB: 33, Topology: 33, Topology_Rich: 33, TEST: 33, Topology_Dynamic: 33, TEST_CCCC: 33       |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Total      |       |        | 600          | SOMEDB: 100, Topology_Rich: 100, Topology: 100, TEST_CCCC: 100, Topology_Dynamic: 100, TEST: 100 | TEST_CCCC: 100, Topology: 100, Topology_Rich: 100, SOMEDB: 100, TEST: 100, Topology_Dynamic: 100 |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Got 4 rows (Time spent: 1.98/3.816 ms)

Tue Oct 27 05:48:50 2020

min.wu · 2020 年10 月 27 日 06:36

看上去机械盘完全搞不动啊，为什么持续有这么多disk write，是一直在compaction做不完了？

你用了几台机器，每个机器部署了几个storaged？

你还是先换release 1.1吧，nightly的问题很可能是已修复的。

另外，我的经验是机械盘基本跑不出性能的。

Les1ie · 2020 年10 月 27 日 07:14

1台机器，3个storaged，参数都没改，直接用的仓库的docker-compose.yaml
https://github.com/vesoft-inc/nebula-docker-compose

抱歉，刚刚得知我执行 dstat 命令的时候后台新开了个导入任务，造成了比较高的持续写入的问题，影响了此处的判断。

早晨提问的时候的 vmstat 的命令的输出是没有执行其他任务的情况下磁盘的 io 情况，每秒读2000个块左右，写500个块.

请问有没有推荐的迁移的方式，库里面目前大概有20亿个节点，我使用 db_dump 工具导出来大约有300GB+，但是这个结果似乎不能直接导入到新的nebula中，还需要二次处理才可以

min.wu · 2020 年10 月 27 日 07:41

直接升级rpm或者docker版本就行了，不用导出来，数据格式是兼容的。
一台物理机其实部署一个storaged就够了，多了没啥用。这个文件示意其实是给多个机器ip的情况。
3个storaged之间还得rpc，有点浪费性能。

Les1ie · 2020 年10 月 27 日 07:58

好的，我稍后尝试升级，看看能不能解决这个问题，谢谢~

建议放一个 best practice 版本的 docker-compose在 https://docs.nebula-graph.com.cn/manual-CN/3.build-develop-and-administration/2.install/3.install-with-docker/ 这里面，或者在文档说明一下这里面为什么开这么多个实例的原因

min.wu · 2020 年10 月 27 日 09:01

docker-compose up之前先看下物理机swap啥情况。

Les1ie · 2020 年10 月 27 日 09:14

因为 nebula 还承载着业务，短期内可能不会重启数据库
我先尝试用 v1.1.0 新开一个机器，把数据导出来再导进去，之后再做故障排查吧

问题暂时告一段落，感谢各位的回复

henson · 2020 年10 月 27 日 09:18

get，我目前也是原始版本，怕升级后出问题，暂时就不动了

min.wu · 2020 年10 月 27 日 09:27

这么高的swap，nightly版本，运行生产？这是时刻准备救(pao)火(lu)的节奏啊。

Les1ie · 2020 年10 月 27 日 10:10

目前正在部署新的机器，准备导入数据，希望不会出问题吧

min.wu · 2020 年10 月 28 日 01:53

Les1ie · 2020 年10 月 29 日 09:06

数据迁移完成，新开了一台虚拟机分的 8c 64G 2T hdd， docker-compose部署运行 v1.1.0，storaged/metad/graphd 各一个，replica=1

在刚导入完之后似乎有个重新均衡负载的过程，磁盘读写比较高，大约完成之后的几个小时cpu占用降低到0，稳定之后硬盘占用 98G，内存 20G

btw，导入过程中发现 nebula_importer 读取超过2万行的 config.yaml 会读取失败，人工拆分到2000行就可以正常运行了

上线上线

yee · 2020 年10 月 29 日 10:36

麻烦问一下 nebula-importer 读取大文件失败的原因是什么？有什么错误输出吗？

Les1ie · 2020 年10 月 29 日 12:25

提了个issue
https://github.com/vesoft-inc/nebula-importer/issues/95