search

yinqiwen / ardb

A redis protocol compatible nosql, it support multiple storage engines as backend like Google's LevelDB, Facebook's RocksDB, OpenLDAP's LMDB, PerconaFT, WiredTiger, ForestDB.
BSD 3-Clause "New" or "Revised" License
1.83k stars 278 forks source link

Can't import big snapshot - Error: Connection reset by peer #341

Closed unoexperto closed 6 years ago

unoexperto commented 7 years ago

Hello! I have problems importing big snapshot of production DB. Size of snapshot is ~67GB (68386389464 bytes). From client side prospective it looks like server dropped the connection. I can reconnect with client. Here is how I do import and its output after several hours

localhost:8889> import backup/save-redis-snapshot.292774109975.4613879422269534302.1496580998
Error: Connection reset by peer
(8379.25s)

Content of INFO

localhost:8889> info
# Server
ardb_version:0.9.4
redis_version:2.8.0
engine:rocksdb
ardb_home:/ardb_home
os:Linux 4.10.0-21-generic x86_64
gcc_version:6.2.1
process_id:1
run_id:f5e7e39341547864c4e4f87942b589948952c49e
tcp_port:16379
listen:0.0.0.0:16379
uptime_in_seconds:37867
uptime_in_days:0
executable:/usr/src/ardb/src/ardb-server
config_file:/usr/src/ardb/ardb.conf

# Databases
data_dir:/ardb_home/data
used_disk_space:66134573244
rocksdb_version:5.0.2
rocksdb_memtable_total:29361584
rocksdb_memtable_unflushed:29361584
rocksdb_table_readers_total:11479587

** Compaction Stats [0] **
Level    Files   Size(MB} Score Read(GB}  Rn(GB} Rnp1(GB} Write(GB} Wnew(GB} Moved(GB} W-Amp Rd(MB/s} Wr(MB/s} Comp(sec} Comp(cnt} Avg(sec} KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
  L1     10/0     454.71   0.9      0.9     0.8      0.0       0.9      0.8       0.0   1.1     34.5     34.5        26         1   26.267    322K      0
  L2    247/0    5114.22   1.0      3.2     3.2      0.0       1.1      1.1       0.0   0.3      9.4      3.3       348        51    6.820    404K      0
  L3   2253/0   51195.94   1.0      0.0     0.0      0.0       0.0      0.0      10.1   0.0      0.0      0.0         0         0    0.000       0      0
  L4    232/0    6305.78   0.0      0.0     0.0      0.0       0.0      0.0       6.2   0.0      0.0      0.0         0         0    0.000       0      0
 Sum   2742/0   63070.64   0.0      4.1     4.0      0.0       2.0      2.0      16.3 2144480001.0     11.2      5.5       374        52    7.194    727K      0
 Int      0/0       0.00   0.0      4.1     4.0      0.0       2.0      2.0      16.3 2144480001.0     11.2      5.5       374        52    7.194    727K      0
Uptime(secs): 37866.6 total, 37866.6 interval
Flush(GB): cumulative 0.000, interval 0.000
AddFile(GB): cumulative 0.000, interval 0.000
AddFile(Total Files): cumulative 0, interval 0
AddFile(L0 Files): cumulative 0, interval 0
AddFile(Keys): cumulative 0, interval 0
Cumulative compaction: 2.00 GB write, 0.05 MB/s write, 4.09 GB read, 0.11 MB/s read, 374.1 seconds
Interval compaction: 2.00 GB write, 0.05 MB/s write, 4.09 GB read, 0.11 MB/s read, 374.1 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count

** DB Stats **
Uptime(secs): 37866.6 total, 37866.6 interval
Cumulative writes: 0 writes, 0 keys, 0 commit groups, 0.0 writes per commit group, ingest: 0.00 GB, 0.00 MB/s
Cumulative WAL: 0 writes, 0 syncs, 0.00 writes per sync, written: 0.00 GB, 0.00 MB/s
Cumulative stall: 00:00:0.000 H:M:S, 0.0 percent
Interval writes: 0 writes, 0 keys, 0 commit groups, 0.0 writes per commit group, ingest: 0.00 MB, 0.00 MB/s
Interval WAL: 0 writes, 0 syncs, 0.00 writes per sync, written: 0.00 MB, 0.00 MB/s
Interval stall: 00:00:0.000 H:M:S, 0.0 percent

# Clients
connected_clients:1
blocked_clients:0

# Persistence
loading:0
rdb_last_save_time:0
rdb_last_bgsave_status:ok
rdb_last_bgsave_time_sec:0
rdb_bgsave_in_progress:0
rdb_current_bgsave_time_sec:0

# CPU
used_cpu_sys:1015.92
used_cpu_user:416.37

# Replication
role:master
repl_dir: /ardb_home/repl
repl_current_namespace:
connected_slaves: 0
master_repl_offset: 0
repl_backlog_size: 1073741824
repl_backlog_cache_size: 104857600
repl_backlog_first_byte_offset: 0
repl_backlog_histlen: 1
repl_backlog_cksm: 0000000000000000
snapshot0:type=redis,create_time=Sun Jun  4 12:56:38 2017,name=save-redis-snapshot.292774109975.4613879422269534302.1496580998

# Memory
used_memory_rss:282386432

# Stats
slave_sync_total_commands_processed:0
slave_sync_instantaneous_ops_per_sec:0
total_commands_processed:0
instantaneous_ops_per_sec:0
total_connections_received:1
rejected_connections:0
sync_full:0
sync_partial_ok:0
sync_partial_err:0
pubsub_channels:0
pubsub_patterns:0
expire_scan_keys:0

# Keyspace
db0:keys=53608240

Config file https://www.zerobin.net/?583f1a743d04149d#4KVM7LmPzreuEY/BVRZfus+FSy/NxZgM4UqpVBSF5lY= And finally giant log file: https://www.dropbox.com/s/6orzmxumvlfqypw/ardb.txt.zip?dl=0

Any ideas what to do ? To me this is pretty bad discovery since it means my backups are useless.

yinqiwen commented 7 years ago

is the server crash down when loading redis dump file?

unoexperto commented 7 years ago

Not sure about that. It was working when I woke up. But possibly docker restarted it automatically. I found core file in /data folder. Will it be helpful for you ? Here it is

https://www.dropbox.com/s/moegxfc20a1u0h8/core?dl=0

bernardko commented 6 years ago

I'm also hitting this issue with a large snapshot, around 204GB.

Basically when I attempt to import, I get "Error: Connection reset by peer" and ardb crashes immediately. Here is the log I got:

[7] 10-27 05:25:45,994 INFO Ardb init engine:rocksdb success.
[7] 10-27 05:25:45,994 INFO Add cached snapshot:save-redis-snapshot.289133692001.1489623791778110912.1509051963
[7] 10-27 05:25:45,995 INFO Ardb will accept connections on 0.0.0.0:16379
[7] 10-27 05:25:45,995 INFO Ardb started with version 0.9.4
[7] 10-27 05:26:00,949 INFO Start loading RDB file with format version:6
[7] 10-27 05:26:00,949 INFO [RocksDB]Shutdown: canceling all background work
[7] 10-27 05:26:00,951 INFO [RocksDB]Shutdown complete
[7] 10-27 05:26:00,951 INFO [RocksDB]RocksDB version: 5.2.1

[7] 10-27 05:26:00,951 INFO [RocksDB]Git sha rocksdb_build_git_sha:a4faac3fa39914578407ab40a92d7d1714683876
[7] 10-27 05:26:00,951 INFO [RocksDB]Compile date Oct 19 2017
[7] 10-27 05:26:00,951 INFO [RocksDB]DB SUMMARY

[7] 10-27 05:26:00,951 INFO [RocksDB]CURRENT file:  CURRENT

[7] 10-27 05:26:00,952 INFO [RocksDB]IDENTITY file:  IDENTITY

[7] 10-27 05:26:00,952 INFO [RocksDB]MANIFEST file:  MANIFEST-000058 size: 112 Bytes

[7] 10-27 05:26:00,952 INFO [RocksDB]SST files in /var/lib/ardb/data/rocksdb dir, Total Num: 0, files: 

[7] 10-27 05:26:00,952 INFO [RocksDB]Write Ahead Log file in /var/lib/ardb/data/rocksdb: 000059.log size: 0 ; 

[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.error_if_exists: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.create_if_missing: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.paranoid_checks: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                                    Options.env: 0xa48ac0
[7] 10-27 05:26:00,952 INFO [RocksDB]                               Options.info_log: 0x7f3c3e588580
[7] 10-27 05:26:00,952 INFO [RocksDB]                         Options.max_open_files: 10000
[7] 10-27 05:26:00,952 INFO [RocksDB]               Options.max_file_opening_threads: 16
[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.disableDataSync: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                              Options.use_fsync: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.max_log_file_size: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                 Options.max_manifest_file_size: 18446744073709551615
[7] 10-27 05:26:00,952 INFO [RocksDB]                  Options.log_file_time_to_roll: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.keep_log_file_num: 1000
[7] 10-27 05:26:00,952 INFO [RocksDB]                   Options.recycle_log_file_num: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.allow_fallocate: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                       Options.allow_mmap_reads: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.allow_mmap_writes: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                       Options.use_direct_reads: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                       Options.use_direct_writes: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]         Options.create_missing_column_families: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                             Options.db_log_dir: 
[7] 10-27 05:26:00,952 INFO [RocksDB]                                Options.wal_dir: /var/lib/ardb/data/rocksdb
[7] 10-27 05:26:00,952 INFO [RocksDB]               Options.table_cache_numshardbits: 6
[7] 10-27 05:26:00,952 INFO [RocksDB]                     Options.max_subcompactions: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                 Options.max_background_flushes: 4
[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.WAL_ttl_seconds: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.WAL_size_limit_MB: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.manifest_preallocation_size: 4194304
[7] 10-27 05:26:00,952 INFO [RocksDB]                    Options.is_fd_close_on_exec: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                  Options.stats_dump_period_sec: 600
[7] 10-27 05:26:00,952 INFO [RocksDB]                  Options.advise_random_on_open: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                   Options.db_write_buffer_size: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]        Options.access_hint_on_compaction_start: 1
[7] 10-27 05:26:00,952 INFO [RocksDB] Options.new_table_reader_for_compaction_inputs: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]              Options.compaction_readahead_size: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]          Options.random_access_max_buffer_size: 1048576
[7] 10-27 05:26:00,952 INFO [RocksDB]          Options.writable_file_max_buffer_size: 1048576
[7] 10-27 05:26:00,952 INFO [RocksDB]                     Options.use_adaptive_mutex: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                           Options.rate_limiter: 0x7f3c3e442900
[7] 10-27 05:26:00,952 INFO [RocksDB]    Options.sst_file_manager.rate_bytes_per_sec: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                         Options.bytes_per_sync: 1048576
[7] 10-27 05:26:00,952 INFO [RocksDB]                     Options.wal_bytes_per_sync: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]                      Options.wal_recovery_mode: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]                 Options.enable_thread_tracking: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]        Options.allow_concurrent_memtable_write: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]     Options.enable_write_thread_adaptive_yield: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.write_thread_max_yield_usec: 100
[7] 10-27 05:26:00,952 INFO [RocksDB]           Options.write_thread_slow_yield_usec: 3
[7] 10-27 05:26:00,952 INFO [RocksDB]                              Options.row_cache: None
[7] 10-27 05:26:00,952 INFO [RocksDB]                             Options.wal_filter: None
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.avoid_flush_during_recovery: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.base_background_compactions: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.max_background_compactions: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.avoid_flush_during_shutdown: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.delayed_write_rate : 16777216
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.max_total_wal_size: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.delete_obsolete_files_period_micros: 21600000000
[7] 10-27 05:26:00,952 INFO [RocksDB]Compression algorithms supported:
[7] 10-27 05:26:00,952 INFO [RocksDB]   Snappy supported: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]   Zlib supported: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]   Bzip supported: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]   LZ4 supported: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]   ZSTD supported: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]Fast CRC32 supported: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Recovering from manifest file: MANIFEST-000058

[7] 10-27 05:26:00,952 INFO [RocksDB]--------------- Options for column family [default]:

[7] 10-27 05:26:00,952 INFO [RocksDB]              Options.comparator: ardb.comparator
[7] 10-27 05:26:00,952 INFO [RocksDB]          Options.merge_operator: ardb.merger
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compaction_filter: None
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compaction_filter_factory: ardb.compact_filter_factory
[7] 10-27 05:26:00,952 INFO [RocksDB]        Options.memtable_factory: SkipListFactory
[7] 10-27 05:26:00,952 INFO [RocksDB]           Options.table_factory: BlockBasedTable
[7] 10-27 05:26:00,952 INFO [RocksDB]           table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7f3c3e433368)
  cache_index_and_filter_blocks: 0
  cache_index_and_filter_blocks_with_high_priority: 0
  pin_l0_filter_and_index_blocks_in_cache: 0
  index_type: 0
  hash_index_allow_collision: 1
  checksum: 1
  no_block_cache: 0
  block_cache: 0x7f3c3e5800f8
  block_cache_name: LRUCache
  block_cache_options:
    capacity : 536870912
    num_shard_bits : 6
    strict_capacity_limit : 0
    high_pri_pool_ratio: 0.000
  block_cache_compressed: (nil)
  persistent_cache: (nil)
  block_size: 4096
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  filter_policy: rocksdb.BuiltinBloomFilter
  whole_key_filtering: 1
  skip_table_builder_flush: 0
  format_version: 2

[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.write_buffer_size: 134217728
[7] 10-27 05:26:00,952 INFO [RocksDB] Options.max_write_buffer_number: 6
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[0]: NoCompression
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[1]: NoCompression
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[2]: Snappy
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[3]: Snappy
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[4]: Snappy
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[5]: Snappy
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.compression[6]: Snappy
[7] 10-27 05:26:00,952 INFO [RocksDB]                 Options.bottommost_compression: Disabled
[7] 10-27 05:26:00,952 INFO [RocksDB]      Options.prefix_extractor: ardb.prefix_extractor
[7] 10-27 05:26:00,952 INFO [RocksDB]  Options.memtable_insert_with_hint_prefix_extractor: nullptr
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.num_levels: 7
[7] 10-27 05:26:00,952 INFO [RocksDB]       Options.min_write_buffer_number_to_merge: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]    Options.max_write_buffer_number_to_maintain: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]           Options.compression_opts.window_bits: -14
[7] 10-27 05:26:00,952 INFO [RocksDB]                 Options.compression_opts.level: -1
[7] 10-27 05:26:00,952 INFO [RocksDB]              Options.compression_opts.strategy: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]        Options.compression_opts.max_dict_bytes: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]     Options.level0_file_num_compaction_trigger: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]         Options.level0_slowdown_writes_trigger: 20
[7] 10-27 05:26:00,952 INFO [RocksDB]             Options.level0_stop_writes_trigger: 36
[7] 10-27 05:26:00,952 INFO [RocksDB]                  Options.target_file_size_base: 67108864
[7] 10-27 05:26:00,952 INFO [RocksDB]            Options.target_file_size_multiplier: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]               Options.max_bytes_for_level_base: 536870912
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.level_compaction_dynamic_level_bytes: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]         Options.max_bytes_for_level_multiplier: 10.000000
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[0]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[1]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[2]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[3]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[4]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[5]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[6]: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]      Options.max_sequential_skip_in_iterations: 8
[7] 10-27 05:26:00,952 INFO [RocksDB]                   Options.max_compaction_bytes: 1677721600
[7] 10-27 05:26:00,952 INFO [RocksDB]                       Options.arena_block_size: 16777216
[7] 10-27 05:26:00,952 INFO [RocksDB]  Options.soft_pending_compaction_bytes_limit: 68719476736
[7] 10-27 05:26:00,952 INFO [RocksDB]  Options.hard_pending_compaction_bytes_limit: 274877906944
[7] 10-27 05:26:00,952 INFO [RocksDB]      Options.rate_limit_delay_max_milliseconds: 100
[7] 10-27 05:26:00,952 INFO [RocksDB]               Options.disable_auto_compactions: 0
[7] 10-27 05:26:00,952 INFO [RocksDB]          Options.verify_checksums_in_compaction: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]                        Options.compaction_style: kCompactionStyleLevel
[7] 10-27 05:26:00,952 INFO [RocksDB]                          Options.compaction_pri: kByCompensatedSize
[7] 10-27 05:26:00,952 INFO [RocksDB] Options.compaction_options_universal.size_ratio: 1
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.compaction_options_universal.min_merge_width: 2
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.compaction_options_universal.max_merge_width: 4294967295
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.compaction_options_universal.max_size_amplification_percent: 200
[7] 10-27 05:26:00,952 INFO [RocksDB]Options.compaction_options_universal.compression_size_percent: -1
[7] 10-27 05:26:00,953 INFO [RocksDB]Options.compaction_options_fifo.max_table_files_size: 1073741824
[7] 10-27 05:26:00,953 INFO [RocksDB]                  Options.table_properties_collectors: 
[7] 10-27 05:26:00,953 INFO [RocksDB]                  Options.inplace_update_support: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]                Options.inplace_update_num_locks: 10000
[7] 10-27 05:26:00,953 INFO [RocksDB]              Options.min_partial_merge_operands: 2
[7] 10-27 05:26:00,953 INFO [RocksDB]              Options.memtable_prefix_bloom_size_ratio: 0.100000
[7] 10-27 05:26:00,953 INFO [RocksDB]  Options.memtable_huge_page_size: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]                          Options.bloom_locality: 1
[7] 10-27 05:26:00,953 INFO [RocksDB]                   Options.max_successive_merges: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]               Options.optimize_filters_for_hits: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]               Options.paranoid_file_checks: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]               Options.force_consistency_checks: 0
[7] 10-27 05:26:00,953 INFO [RocksDB]               Options.report_bg_io_stats: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]--------------- Options for column family [0]:

[7] 10-27 05:26:00,955 INFO [RocksDB]              Options.comparator: ardb.comparator
[7] 10-27 05:26:00,955 INFO [RocksDB]          Options.merge_operator: ardb.merger
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compaction_filter: None
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compaction_filter_factory: ardb.compact_filter_factory
[7] 10-27 05:26:00,955 INFO [RocksDB]        Options.memtable_factory: SkipListFactory
[7] 10-27 05:26:00,955 INFO [RocksDB]           Options.table_factory: BlockBasedTable
[7] 10-27 05:26:00,955 INFO [RocksDB]           table_factory options:   flush_block_policy_factory: FlushBlockBySizePolicyFactory (0x7f3c3e433368)
  cache_index_and_filter_blocks: 0
  cache_index_and_filter_blocks_with_high_priority: 0
  pin_l0_filter_and_index_blocks_in_cache: 0
  index_type: 0
  hash_index_allow_collision: 1
  checksum: 1
  no_block_cache: 0
  block_cache: 0x7f3c3e5800f8
  block_cache_name: LRUCache
  block_cache_options:
    capacity : 536870912
    num_shard_bits : 6
    strict_capacity_limit : 0
    high_pri_pool_ratio: 0.000
  block_cache_compressed: (nil)
  persistent_cache: (nil)
  block_size: 4096
  block_size_deviation: 10
  block_restart_interval: 16
  index_block_restart_interval: 1
  filter_policy: rocksdb.BuiltinBloomFilter
  whole_key_filtering: 1
  skip_table_builder_flush: 0
  format_version: 2

[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.write_buffer_size: 134217728
[7] 10-27 05:26:00,955 INFO [RocksDB] Options.max_write_buffer_number: 6
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[0]: NoCompression
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[1]: NoCompression
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[2]: Snappy
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[3]: Snappy
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[4]: Snappy
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[5]: Snappy
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.compression[6]: Snappy
[7] 10-27 05:26:00,955 INFO [RocksDB]                 Options.bottommost_compression: Disabled
[7] 10-27 05:26:00,955 INFO [RocksDB]      Options.prefix_extractor: ardb.prefix_extractor
[7] 10-27 05:26:00,955 INFO [RocksDB]  Options.memtable_insert_with_hint_prefix_extractor: nullptr
[7] 10-27 05:26:00,955 INFO [RocksDB]            Options.num_levels: 7
[7] 10-27 05:26:00,955 INFO [RocksDB]       Options.min_write_buffer_number_to_merge: 2
[7] 10-27 05:26:00,955 INFO [RocksDB]    Options.max_write_buffer_number_to_maintain: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]           Options.compression_opts.window_bits: -14
[7] 10-27 05:26:00,955 INFO [RocksDB]                 Options.compression_opts.level: -1
[7] 10-27 05:26:00,955 INFO [RocksDB]              Options.compression_opts.strategy: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]        Options.compression_opts.max_dict_bytes: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]     Options.level0_file_num_compaction_trigger: 2
[7] 10-27 05:26:00,955 INFO [RocksDB]         Options.level0_slowdown_writes_trigger: 20
[7] 10-27 05:26:00,955 INFO [RocksDB]             Options.level0_stop_writes_trigger: 36
[7] 10-27 05:26:00,955 INFO [RocksDB]                  Options.target_file_size_base: 67108864
[7] 10-27 05:26:00,955 INFO [RocksDB]            Options.target_file_size_multiplier: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.max_bytes_for_level_base: 536870912
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.level_compaction_dynamic_level_bytes: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]         Options.max_bytes_for_level_multiplier: 10.000000
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[0]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[1]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[2]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[3]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[4]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[5]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.max_bytes_for_level_multiplier_addtl[6]: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]      Options.max_sequential_skip_in_iterations: 8
[7] 10-27 05:26:00,955 INFO [RocksDB]                   Options.max_compaction_bytes: 1677721600
[7] 10-27 05:26:00,955 INFO [RocksDB]                       Options.arena_block_size: 16777216
[7] 10-27 05:26:00,955 INFO [RocksDB]  Options.soft_pending_compaction_bytes_limit: 68719476736
[7] 10-27 05:26:00,955 INFO [RocksDB]  Options.hard_pending_compaction_bytes_limit: 274877906944
[7] 10-27 05:26:00,955 INFO [RocksDB]      Options.rate_limit_delay_max_milliseconds: 100
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.disable_auto_compactions: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]          Options.verify_checksums_in_compaction: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]                        Options.compaction_style: kCompactionStyleLevel
[7] 10-27 05:26:00,955 INFO [RocksDB]                          Options.compaction_pri: kByCompensatedSize
[7] 10-27 05:26:00,955 INFO [RocksDB] Options.compaction_options_universal.size_ratio: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.compaction_options_universal.min_merge_width: 2
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.compaction_options_universal.max_merge_width: 4294967295
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.compaction_options_universal.max_size_amplification_percent: 200
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.compaction_options_universal.compression_size_percent: -1
[7] 10-27 05:26:00,955 INFO [RocksDB]Options.compaction_options_fifo.max_table_files_size: 1073741824
[7] 10-27 05:26:00,955 INFO [RocksDB]                  Options.table_properties_collectors: 
[7] 10-27 05:26:00,955 INFO [RocksDB]                  Options.inplace_update_support: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]                Options.inplace_update_num_locks: 10000
[7] 10-27 05:26:00,955 INFO [RocksDB]              Options.min_partial_merge_operands: 2
[7] 10-27 05:26:00,955 INFO [RocksDB]              Options.memtable_prefix_bloom_size_ratio: 0.100000
[7] 10-27 05:26:00,955 INFO [RocksDB]  Options.memtable_huge_page_size: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]                          Options.bloom_locality: 1
[7] 10-27 05:26:00,955 INFO [RocksDB]                   Options.max_successive_merges: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.optimize_filters_for_hits: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.paranoid_file_checks: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.force_consistency_checks: 0
[7] 10-27 05:26:00,955 INFO [RocksDB]               Options.report_bg_io_stats: 0
[7] 10-27 05:26:00,957 INFO [RocksDB]Recovered from manifest file:/var/lib/ardb/data/rocksdb/MANIFEST-000058 succeeded,manifest_file_number is 58, next_file_number is 60, last_sequence is 1, log_number is 0,prev_log_number is 0,max_column_family is 3

[7] 10-27 05:26:00,957 INFO [RocksDB]Column family [default] (ID 0), log number is 57

[7] 10-27 05:26:00,957 INFO [RocksDB]Column family [0] (ID 3), log number is 57

[7] 10-27 05:26:00,957 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509081960957642, "job": 1, "event": "recovery_started", "log_files": [59]}
[7] 10-27 05:26:00,957 INFO [RocksDB]Recovering log #59 mode 2
[7] 10-27 05:26:00,957 INFO [RocksDB]Creating manifest 61

[7] 10-27 05:26:00,959 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509081960959688, "job": 1, "event": "recovery_finished"}
[7] 10-27 05:26:00,964 INFO [RocksDB]DB pointer 0x7f3c38069000
[7] 10-27 05:26:00,964 INFO RocksDB open column family:default success.
[7] 10-27 05:26:00,964 INFO RocksDB open column family:0 success.
[7] 10-27 05:26:00,964 ERROR Unknown object type:111
bernardko commented 6 years ago

So it looks like its trying to load some REDIS_RDB_TYPE with value 111 which is hitting the default case for the switch in RedisLoadObject.

Not sure if this is really related to this issue.

yinqiwen commented 6 years ago

@bernardko what is the version of the redis dump file?

yinqiwen commented 6 years ago

@bernardko seems related with this commit https://github.com/yinqiwen/ardb/commit/bcfddc7fefa4d59679adee3d9e61ec69d3750b35

bernardko commented 6 years ago

Are you asking about backup-file-format in the config? I left it as default.

backup-file-format                ardb
bernardko commented 6 years ago

I'll give that commit a test run. thanks!

unoexperto commented 6 years ago

I'll be quite excited if you guys fix this. I had to move away from ARDB because of it to my custom wrapper around RocksDBJNI.

Also I highly recommend switching from rocksdb 5.2.1 @yinqiwen. I find it unreliable with writes. I was losing data in production (my DB is 1TB right now). I'm on 5.7.2 right now

bernardko commented 6 years ago

Just ran it on the new commit but unfortunately I'm getting the same error.

[7] 10-27 08:35:45,769 ERROR Unknown object type:111

Is there anymore information I can provide to help debug this problem?

yinqiwen commented 6 years ago

@bernardko what is the key types stored in the snapshot?

bernardko commented 6 years ago

@unoexperto I really want to get this fixed as its blocker to using ardb in production for me too.

bernardko commented 6 years ago

@yinqiwen In the snapshot, there are SETs, HSETs, ZSETs and LISTs.

yinqiwen commented 6 years ago

@bernardko is the snapshot generated by latest code or redis?

bernardko commented 6 years ago

~~The snapshot is generated by the latest code.~ Actually more accurately it was generated by a4faac3fa39914578407ab40a92d7d1714683876

Should I try generating the snapshot using the latest code?

bernardko commented 6 years ago

@yinqiwen Just tried to generate a new snapshot on the latest commit but it failed with the following errors:

Also noticed that it deleted my old snapshot that I couldn't import previously because its too old. 

[6] 10-27 21:02:06,393 WARN Remove snapshot:/var/lib/ardb-backup/save-redis-snapshot.289133692001.1489623791778110912.1509051963 since it's too old with offset:289133692001
[6] 10-27 21:02:06,393 WARN Remove snapshot file:/var/lib/ardb-backup/save-redis-snapshot.289133692001.1489623791778110912.1509051963
[6] 10-27 21:02:56,887 INFO RocksDB drop column family:0.
[6] 10-27 21:02:56,898 INFO [RocksDB]Dropped column family with id 1

[6] 10-27 21:02:56,899 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509138176899132, "job": 0, "event": "table_file_deletion", "file_number": 15936}
[6] 10-27 21:02:56,899 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509138176899417, "job": 0, "event": "table_file_deletion", "file_number": 15502}
[6] 10-27 21:02:56,899 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509138176899866, "job": 0, "event": "table_file_deletion", "file_number": 15501}
[6] 10-27 21:03:11,487 INFO RocksDB drop column family:2.
[6] 10-27 21:03:11,496 INFO [RocksDB]Dropped column family with id 4

[6] 10-27 21:03:11,498 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509138191498780, "job": 0, "event": "table_file_deletion", "file_number": 15497}
[6] 10-27 21:03:11,501 INFO [RocksDB]EVENT_LOG_v1 {"time_micros": 1509138191501928, "job": 0, "event": "table_file_deletion", "file_number": 14229}
[6] 10-27 21:04:32,466 INFO Close write latch for snapshot save preparing start.
[6] 10-27 21:04:32,466 INFO Open write latch for snapshot save preparing complete.
[6] 10-27 21:08:40,560 ERROR Previous key:message:1:priority:high with type:5 is not complete dump, 3000 missing in 31926556 elements
[6] 10-27 21:08:40,623 ERROR Failed to write dump file for reason code:-2
[6] 10-27 21:08:40,623 WARN Failed to save snapshot file with type:redis
[6] 10-27 21:08:40,623 WARN Remove snapshot file:/var/lib/ardb-backup/save-redis-snapshot.1509138272466.tmp

For your information, message:1:priority:high is a queue which my application pops 3000 messsages at a time from.

bernardko commented 6 years ago

@yinqiwen I tried separating and regenerating a dataset from a different part of my application using an empty ardb and tried generating a snapshot and importing. Getting the same error as before but with a different object type number.

This dataset has HSETs and SETs only.

[7] 10-27 21:33:37,368 ERROR Unknown object type:56

ardb also crashes after this error.

Hope this information gives you a few more clues as to what is going on. Please let me know if there is any further info I can provide.

yinqiwen commented 6 years ago

@bernardko is there any write operation executed when saving snapshot?

bernardko commented 6 years ago

Just to make sure I tried this again and double checked that all my applications were stopped. I'm getting the same error.

[6] 10-28 21:38:15,031 ERROR Previous key:message:1:priority:high with type:5 is not complete dump, 3000 missing in 33482586 elements
[6] 10-28 21:38:15,031 ERROR Failed to write dump file for reason code:-2
[6] 10-28 21:38:15,031 WARN Failed to save snapshot file with type:redis
[6] 10-28 21:38:15,031 WARN Remove snapshot file:/var/lib/ardb-backup/save-redis-snapshot.1509226497281.tmp
yinqiwen commented 6 years ago

@bernardko 3000 missing in 33482586 elements means the length stored in the list meta value is 33482586, but there is only 33482586 - 3000 elements. which operation are u used to delete elements for lists?

bernardko commented 6 years ago

@yinqiwen I'm using lrange and ltrim in a pipeline to delete elements from the list.

1509241723.698964 "lrange" "message:1:priority:high" "0" "2999"
1509241723.725610 "ltrim" "message:1:priority:high" "3000" "-1"
bernardko commented 6 years ago

@yinqiwen I was just testing to see if I can narrow down any clues to why I was getting the "ERROR Unknown object type:56" error with my particular dataset.

I found that it affected SETs that had a cardinality greater than 16383 with my dataset.

Here is what I tested:

127.0.0.1:6379[2]> FLUSHALL
OK
127.0.0.1:6379[2]> KEYS *
1) "message:11:fail_type:0"
127.0.0.1:6379[2]> TYPE message:11:fail_type:0
"set"
127.0.0.1:6379[2]> scard message:11:fail_type:0
(integer) 16383
127.0.0.1:6379[2]> BGSAVE
OK
127.0.0.1:6379[2]> FLUSHALL
OK
127.0.0.1:6379[2]> import /var/lib/ardb/backup/save-redis-snapshot.1438638672.4724544814123957252.1509241196
OK

The above is okay, then I flushed the database and generated another dataset with cardinality 16384:

127.0.0.1:6379[2]> FLUSHALL
OK
127.0.0.1:6379[2]> TYPE message:11:fail_type:0
"set"
127.0.0.1:6379[2]> KEYS *
1) "message:11:fail_type:0"
127.0.0.1:6379[2]> scard message:11:fail_type:0
(integer) 16384
127.0.0.1:6379[2]> BGSAVE
OK
127.0.0.1:6379[2]> import /var/lib/ardb/backup/save-redis-snapshot.1437360617.8932898519262761033.1509241034
Error: Connection reset by peer

The error in the logs show:

[7] 10-29 02:08:39,756 ERROR Unknown object type:32

I noticed that I'm getting this error with ZSETs as well.

yinqiwen commented 6 years ago

@unoexperto is the value stored in SETs is integer?

bernardko commented 6 years ago

@yinqiwen No, they are all strings.

yinqiwen commented 6 years ago

latest commit would fix the bug when length is greater than 1<<14, the bug may crash the server .

bernardko commented 6 years ago

@yinqiwen Great thanks, saving importing the snapshot from my test cases are working now.

unoexperto commented 6 years ago

@bernardko @yinqiwen Are you guys confirming that master branch no longer crashes on backup recovery ?

yinqiwen commented 6 years ago

@unoexperto the crash is fixed by https://github.com/yinqiwen/ardb/commit/13b99efd7c8e51358dca207748718453af08dda1