cluster stops working

[joruxs]

Hi, I am testing out nebula-graph 3.1.0.

I created a cluster of 6 machines (1-3 with metad, 1-6 with graphd+storaged) and have been running some ingestion tests with my own data ingestor (java program). It has been working well overall but I have noticed a few issues with cluster stability.

I have tested primarily with replica factor 1 but now when switching to 3 I started running into these errors (from graphd err log):

E20220511 09:14:56.591831 696 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 9
E20220511 09:14:56.591840 696 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 79
E20220511 09:14:56.591850 696 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 11
E20220511 09:14:56.591861 696 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 91
E20220511 09:14:56.591902 696 QueryInstance.cpp:137] Storage Error: Not the leader of 25. Please retry later.

I have tried rebooting nodes and they seems to come up and ONLINE again according to SHOW HOSTS.

I also removed the space and use an entirely new space name but I get the same errors.

Any ideas, tips what could be causing this?

[joruxs]

Although I don't understand it fully I think I may have found a solution for my problem.

For each test run I started with

• Remove old schema
• Create new schema
• Wait 20 seconds.
• Insert data...

I have heartbeat interval default (10 seconds) and thus thought waiting 20 seconds would be sufficient. However, it turns out that increasing the wait to 40 seconds solved the problem. Now I don't see the E_LEADER CHANGED messages any more.

[wey-gu]

Thanks, looks good from the print.

The leader changed is just indicating a leader change and I could not relate it to schema change before the schema is sync-ed in heartbeat, errors related to the unexpected schema(i.e. no such tag) are expected.

Are there any abnormal logs in storaged/metad, please?

[wey-gu]

The configurations are default ones, right? would you mind sharing them, too?

[joruxs]

The only log which contains anything is graphd-stderr.log on the cluster node I contact with my client program. It prints this on a failure:

E20220512 12:03:21.641758 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 23
E20220512 12:03:21.641820 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 21
E20220512 12:03:21.641834 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 19
E20220512 12:03:21.641844 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 11
E20220512 12:03:21.641855 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 15
E20220512 12:03:21.641865 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 27
E20220512 12:03:21.641876 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 5
E20220512 12:03:21.641886 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 25
E20220512 12:03:21.641896 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 9
E20220512 12:03:21.641906 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 13
E20220512 12:03:21.641916 26089 StorageAccessExecutor.h:39] InsertVerticesExecutor failed, error E_LEADER_CHANGED, part 7
E20220512 12:03:21.641943 26089 QueryInstance.cpp:137] Storage Error: Not the leader of 23. Please retry later.

The configuration files are based on the .default templates from 3.1.0 (tar.gz):

nebula-vm001:/etc/nebula$ grep "^--" metad.conf
--daemonize=true
--pid_file=pids/nebula-metad.pid
--log_dir=logs
--minloglevel=0
--v=0
--logbufsecs=0
--redirect_stdout=true
--stdout_log_file=metad-stdout.log
--stderr_log_file=metad-stderr.log
--stderrthreshold=2
--timestamp_in_logfile_name=true
--meta_server_addrs=10.83.0.12:9559,10.83.0.26:9559,10.83.0.52:9559
--local_ip=10.83.0.12
--port=9559
--ws_ip=0.0.0.0
--ws_http_port=19559
--ws_storage_http_port=19779
--data_path=data/meta
--default_parts_num=100
--default_replica_factor=1
--heartbeat_interval_secs=10
--agent_heartbeat_interval_secs=60

nebula-vm001:/etc/nebula$ grep "^--" graphd.conf
--daemonize=true
--pid_file=pids/nebula-graphd.pid
--enable_optimizer=true
--default_charset=utf8
--default_collate=utf8_bin
--local_config=true
--log_dir=logs
--minloglevel=0
--v=0
--logbufsecs=0
--redirect_stdout=true
--stdout_log_file=graphd-stdout.log
--stderr_log_file=graphd-stderr.log
--stderrthreshold=2
--timestamp_in_logfile_name=true
--accept_partial_success=false
--max_allowed_query_size=4194304
--meta_server_addrs=10.83.0.12:9559,10.83.0.26:9559,10.83.0.52:9559
--local_ip=10.83.0.12
--listen_netdev=any
--port=9669
--reuse_port=false
--listen_backlog=1024
--client_idle_timeout_secs=28800
--session_idle_timeout_secs=28800
--num_accept_threads=1
--num_netio_threads=0
--num_worker_threads=0
--ws_ip=0.0.0.0
--ws_http_port=19669
--storage_client_timeout_ms=60000
--ws_meta_http_port=19559
--enable_authorize=false
--auth_type=password
--system_memory_high_watermark_ratio=0.8
--enable_space_level_metrics=false
--enable_experimental_feature=false

nebula-vm001:/etc/nebula$ grep "^--" storaged.conf
--daemonize=true
--pid_file=pids/nebula-storaged.pid
--local_config=true
--log_dir=logs
--minloglevel=0
--v=0
--logbufsecs=0
--redirect_stdout=true
--stdout_log_file=storaged-stdout.log
--stderr_log_file=storaged-stderr.log
--stderrthreshold=2
--timestamp_in_logfile_name=true
--meta_server_addrs=10.83.0.12:9559,10.83.0.26:9559,10.83.0.52:9559
--local_ip=10.83.0.12
--port=9779
--ws_ip=0.0.0.0
--ws_http_port=19779
--heartbeat_interval_secs=10
--raft_heartbeat_interval_secs=30
--raft_rpc_timeout_ms=500
--wal_ttl=14400
--data_path=data/storage
--minimum_reserved_bytes=268435456
--rocksdb_batch_size=4096
--rocksdb_block_cache=4
--engine_type=rocksdb
--rocksdb_compression=lz4
--rocksdb_compression_per_level=
--enable_rocksdb_statistics=false
--rocksdb_stats_level=kExceptHistogramOrTimers
--enable_rocksdb_prefix_filtering=true
--enable_rocksdb_whole_key_filtering=false
--rocksdb_enable_kv_separation=false
--rocksdb_kv_separation_threshold=100
--rocksdb_blob_compression=lz4
--rocksdb_enable_blob_garbage_collection=true
--rocksdb_db_options={}
--rocksdb_column_family_options={"write_buffer_size":"67108864","max_write_buffer_number":"4","max_bytes_for_level_base":"268435456"}
--rocksdb_block_based_table_options={"block_size":"8192"}

[wey-gu]

Thanks, @joruxs, elegant grep line!

@kikimo do you have more ideas on the conf/log lines?

[joruxs]

Thanks @wey-gu for your answers. I want to add that I found it occurs less if I use less maxConnections and smaller statements. As previously stated I have been running tests and I was streching various parameters to find some sweet spot for ingestion performance of my sample data. I used maxConnections=1000 and had 5000 inserts in same "commit". Lowering these while keeping replication factor 3 seemed to lower chance of hitting the above mentioned Storage error. Anyway I am happy knowing it did not occur a single time when using 30s wait.