tair-opensource / TairHash

A redis module, similar to redis hash, but you can set expiration and version for field.
Apache License 2.0
236 stars 40 forks source link

[CRASH] 在redis6.2.12中偶现崩溃 #51

Open sndwow opened 1 year ago

sndwow commented 1 year ago

=== REDIS BUG REPORT START: Cut & paste starting from here === 20232:M 19 Jun 2023 17:16:19.484 # Redis 6.2.12 crashed by signal: 11, si_code: 128 20232:M 19 Jun 2023 17:16:19.484 # Accessing address: (nil) 20232:M 19 Jun 2023 17:16:19.484 # Crashed running the instruction at: 0x7febea236891

------ STACK TRACE ------ EIP: /usr/local/redis/bin/module/tair_hash.so(+0x1891)[0x7febea236891]

Backtrace: /lib64/libpthread.so.0(+0xf630)[0x7febe9727630] /usr/local/redis/bin/module/tair_hash.so(+0x1891)[0x7febea236891] /usr/local/redis/bin/module/tair_hash.so(+0x532f)[0x7febea23a32f] /usr/local/redis/bin/redis-server 0.0.0.0:6379(RedisModuleCommandDispatcher+0x4e)[0x4c201e] /usr/local/redis/bin/redis-server 0.0.0.0:6379(call+0xd5)[0x43ac95] /usr/local/redis/bin/redis-server 0.0.0.0:6379(processCommand+0x57d)[0x43c8dd] /usr/local/redis/bin/redis-server 0.0.0.0:6379(processInputBuffer+0xf3)[0x44f6b3] /usr/local/redis/bin/redis-server 0.0.0.0:6379[0x4e2878] /usr/local/redis/bin/redis-server 0.0.0.0:6379(aeProcessEvents+0x292)[0x433b42] /usr/local/redis/bin/redis-server 0.0.0.0:6379(aeMain+0x1d)[0x433dad] /usr/local/redis/bin/redis-server 0.0.0.0:6379(main+0x311)[0x430031] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7febe936c555] /usr/local/redis/bin/redis-server 0.0.0.0:6379[0x4304f9]

------ REGISTERS ------ 20232:M 19 Jun 2023 17:16:19.485 # RAX:00007febea24f5e0 RBX:0000000000000002 RCX:0000000000000020 RDX:00007febea23ed91 RDI:00007febd6fd0960 RSI:00007febd6fd0960 RBP:0000000000000000 RSP:00007ffcab943910 R8 :0000000000000010 R9 :ffffffffffffffff R10:00007febea251778 R11:0000000000000080 R12:0000000000000001 R13:00007febd5b98080 R14:00007febd5c2d140 R15:653a5f5f6e6f6974 RIP:00007febea236891 EFL:0000000000010202 CSGSFS:0000000000000033 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391f) -> 00007ffcab943a5f 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391e) -> 0000000000000006 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391d) -> 00007febea23a32f 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391c) -> 00007febd698cbb0 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391b) -> 00007ffcab943a10 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab94391a) -> 0005fe77fcce2319 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943919) -> 00007febd5c2d140 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943918) -> 00007febd6006ac0 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943917) -> 00007febea236740 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943916) -> 00007febe91531e0 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943915) -> 00007febd698ba40 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943914) -> 00007febd5add500 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943913) -> 00007febd5b995b0 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943912) -> 00000000e915c538 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943911) -> 00007ffcab943a10 20232:M 19 Jun 2023 17:16:19.485 # (00007ffcab943910) -> 00007febe915f538

------ INFO OUTPUT ------

Server

redis_version:6.2.12 redis_git_sha1:00000000 redis_git_dirty:0 redis_build_id:2f403e6148073f44 redis_mode:standalone os:Linux 3.10.0-1160.90.1.el7.x86_64 x86_64 arch_bits:64 monotonic_clock:POSIX clock_gettime multiplexing_api:epoll atomicvar_api:c11-builtin gcc_version:10.2.1 process_id:20232 process_supervised:no run_id:511d833fcf6ecca6c8f1971421f98e4e7a9766ef tcp_port:6379 server_time_usec:1687166179484441 uptime_in_seconds:66 uptime_in_days:0 hz:10 configured_hz:10 lru_clock:9444579 executable:/usr/local/redis/bin/redis-server config_file:/usr/local/redis/bin/redis.conf io_threads_active:0

Clients

connected_clients:3 cluster_connections:0 maxclients:99968 client_recent_max_input_buffer:41000 client_recent_max_output_buffer:48 blocked_clients:0 tracking_clients:0 clients_in_timeout_table:0

Memory

used_memory:100874768 used_memory_human:96.20M used_memory_rss:112099328 used_memory_rss_human:106.91M used_memory_peak:105685112 used_memory_peak_human:100.79M used_memory_peak_perc:95.45% used_memory_overhead:10460936 used_memory_startup:6259984 used_memory_dataset:90413832 used_memory_dataset_perc:95.56% allocator_allocated:101258952 allocator_active:101863424 allocator_resident:110850048 total_system_memory:33020231680 total_system_memory_human:30.75G used_memory_lua:63488 used_memory_lua_human:62.00K used_memory_scripts:6056 used_memory_scripts_human:5.91K number_of_cached_scripts:17 maxmemory:26843545600 maxmemory_human:25.00G maxmemory_policy:noeviction allocator_frag_ratio:1.01 allocator_frag_bytes:604472 allocator_rss_ratio:1.09 allocator_rss_bytes:8986624 rss_overhead_ratio:1.01 rss_overhead_bytes:1249280 mem_fragmentation_ratio:1.11 mem_fragmentation_bytes:11226960 mem_not_counted_for_evict:0 mem_replication_backlog:0 mem_clients_slaves:0 mem_clients_normal:61544 mem_aof_buffer:0 mem_allocator:jemalloc-5.1.0 active_defrag_running:0 lazyfree_pending_objects:0 lazyfreed_objects:0

Persistence

loading:0 current_cow_size:0 current_cow_size_age:0 current_fork_perc:0.00 current_save_keys_processed:0 current_save_keys_total:0 rdb_changes_since_last_save:1802 rdb_bgsave_in_progress:0 rdb_last_save_time:1687166174 rdb_last_bgsave_status:ok rdb_last_bgsave_time_sec:0 rdb_current_bgsave_time_sec:-1 rdb_last_cow_size:10690560 aof_enabled:0 aof_rewrite_in_progress:0 aof_rewrite_scheduled:0 aof_last_rewrite_time_sec:-1 aof_current_rewrite_time_sec:-1 aof_last_bgrewrite_status:ok aof_last_write_status:ok aof_last_cow_size:0 module_fork_in_progress:0 module_fork_last_cow_size:0

Stats

total_connections_received:4598 total_commands_processed:38722 instantaneous_ops_per_sec:884 total_net_input_bytes:5400871 total_net_output_bytes:637803 instantaneous_input_kbps:112.54 instantaneous_output_kbps:8.84 rejected_connections:0 sync_full:0 sync_partial_ok:0 sync_partial_err:0 expired_keys:1 expired_stale_perc:0.00 expired_time_cap_reached_count:0 expire_cycle_cpu_milliseconds:2 evicted_keys:0 keyspace_hits:150167 keyspace_misses:5733 pubsub_channels:0 pubsub_patterns:0 latest_fork_usec:3294 total_forks:1 migrate_cached_sockets:0 slave_expires_tracked_keys:0 active_defrag_hits:0 active_defrag_misses:0 active_defrag_key_hits:0 active_defrag_key_misses:0 tracking_total_keys:0 tracking_total_items:0 tracking_total_prefixes:0 unexpected_error_replies:0 total_error_replies:68 dump_payload_sanitizations:0 total_reads_processed:39110 total_writes_processed:34455 io_threaded_reads_processed:0 io_threaded_writes_processed:0

Replication

role:master connected_slaves:0 master_failover_state:no-failover master_replid:fc9ad30fb2308a46f3e3172a962462d395ce25aa master_replid2:0000000000000000000000000000000000000000 master_repl_offset:0 second_repl_offset:-1 repl_backlog_active:0 repl_backlog_size:1048576 repl_backlog_first_byte_offset:0 repl_backlog_histlen:0

CPU

used_cpu_sys:0.460402 used_cpu_user:0.842212 used_cpu_sys_children:0.047405 used_cpu_user_children:0.263251 used_cpu_sys_main_thread:0.458837 used_cpu_user_main_thread:0.838200

Modules

module:name=tairzset,ver=1,api=1,filters=0,usedby=[],using=[],options=[] module:name=exstrtype,ver=1,api=1,filters=0,usedby=[],using=[],options=[] module:name=search,ver=20610,api=1,filters=0,usedby=[],using=[],options=[handle-io-errors] module:name=tairhash,ver=1,api=1,filters=0,usedby=[],using=[],options=[]

Commandstats

cmdstat_hdel:calls=2,usec=10,usec_per_call=5.00,rejected_calls=0,failed_calls=0 cmdstat_zrange:calls=330,usec=1112,usec_per_call=3.37,rejected_calls=0,failed_calls=33 cmdstat_exzrevrange:calls=103,usec=2395,usec_per_call=23.25,rejected_calls=0,failed_calls=0 cmdstat_hexists:calls=1,usec=1,usec_per_call=1.00,rejected_calls=0,failed_calls=0 cmdstat_exhkeys:calls=92,usec=219,usec_per_call=2.38,rejected_calls=0,failed_calls=0 cmdstat_sadd:calls=1,usec=3,usec_per_call=3.00,rejected_calls=0,failed_calls=0 cmdstat_ping:calls=6,usec=3,usec_per_call=0.50,rejected_calls=0,failed_calls=0 cmdstat_expire:calls=4114,usec=4185,usec_per_call=1.02,rejected_calls=0,failed_calls=0 cmdstat_zadd:calls=4115,usec=12736,usec_per_call=3.10,rejected_calls=0,failed_calls=0 cmdstat_scan:calls=228,usec=150756,usec_per_call=661.21,rejected_calls=0,failed_calls=0 cmdstat_del:calls=5107,usec=12174,usec_per_call=2.38,rejected_calls=0,failed_calls=0 cmdstat_select:calls=4595,usec=1009,usec_per_call=0.22,rejected_calls=0,failed_calls=0 cmdstat_info:calls=5,usec=294,usec_per_call=58.80,rejected_calls=0,failed_calls=0 cmdstat_hmset:calls=1,usec=7,usec_per_call=7.00,rejected_calls=0,failed_calls=0 cmdstat_exists:calls=3,usec=3,usec_per_call=1.00,rejected_calls=0,failed_calls=0 cmdstat_ltrim:calls=198,usec=71,usec_per_call=0.36,rejected_calls=0,failed_calls=0 cmdstat_exzadd:calls=33,usec=2872,usec_per_call=87.03,rejected_calls=0,failed_calls=0 cmdstat_set:calls=1418,usec=8012,usec_per_call=5.65,rejected_calls=0,failed_calls=0 cmdstat_exzcard:calls=24,usec=41,usec_per_call=1.71,rejected_calls=0,failed_calls=0 cmdstat_zrem:calls=1,usec=5,usec_per_call=5.00,rejected_calls=0,failed_calls=0 cmdstat_zinterstore:calls=55,usec=6259,usec_per_call=113.80,rejected_calls=0,failed_calls=0 cmdstat_zrevrange:calls=5494,usec=12431,usec_per_call=2.26,rejected_calls=0,failed_calls=0 cmdstat_hlen:calls=13,usec=29,usec_per_call=2.23,rejected_calls=0,failed_calls=0 cmdstat_hget:calls=270,usec=784,usec_per_call=2.90,rejected_calls=0,failed_calls=0 cmdstat_exhset:calls=56,usec=1717,usec_per_call=30.66,rejected_calls=0,failed_calls=0 cmdstat_type:calls=15,usec=52,usec_per_call=3.47,rejected_calls=0,failed_calls=0 cmdstat_ttl:calls=17,usec=47,usec_per_call=2.76,rejected_calls=0,failed_calls=0 cmdstat_hgetall:calls=329,usec=1216,usec_per_call=3.70,rejected_calls=1,failed_calls=0 cmdstat_hvals:calls=66,usec=60,usec_per_call=0.91,rejected_calls=0,failed_calls=0 cmdstat_get:calls=867,usec=1038,usec_per_call=1.20,rejected_calls=0,failed_calls=0 cmdstat_zrangebyscore:calls=616,usec=1276,usec_per_call=2.07,rejected_calls=0,failed_calls=0 cmdstat_smembers:calls=90,usec=476,usec_per_call=5.29,rejected_calls=0,failed_calls=0 cmdstat_eval:calls=2189,usec=43351,usec_per_call=19.80,rejected_calls=0,failed_calls=33 cmdstat_lrange:calls=198,usec=209,usec_per_call=1.06,rejected_calls=0,failed_calls=0 cmdstat_hset:calls=1,usec=14,usec_per_call=14.00,rejected_calls=0,failed_calls=0 cmdstat_client:calls=3,usec=5,usec_per_call=1.67,rejected_calls=0,failed_calls=0 cmdstat_hscan:calls=13,usec=130,usec_per_call=10.00,rejected_calls=0,failed_calls=0 cmdstat_scard:calls=159,usec=395,usec_per_call=2.48,rejected_calls=0,failed_calls=0 cmdstat_zremrangebyrank:calls=1,usec=3,usec_per_call=3.00,rejected_calls=0,failed_calls=0 cmdstat_zcard:calls=186,usec=280,usec_per_call=1.51,rejected_calls=0,failed_calls=0 cmdstat_srem:calls=1,usec=3,usec_per_call=3.00,rejected_calls=0,failed_calls=0 cmdstat_zremrangebyscore:calls=649,usec=987,usec_per_call=1.52,rejected_calls=0,failed_calls=0 cmdstat_spop:calls=2457,usec=2409,usec_per_call=0.98,rejected_calls=0,failed_calls=0 cmdstat_exhdelrepl:calls=1,usec=4,usec_per_call=4.00,rejected_calls=0,failed_calls=0 cmdstat_sscan:calls=1,usec=5,usec_per_call=5.00,rejected_calls=0,failed_calls=0 cmdstat_auth:calls=4598,usec=8298,usec_per_call=1.80,rejected_calls=0,failed_calls=0

Errorstats

errorstat_ERR:count=34 errorstat_LOADING:count=1 errorstat_WRONGTYPE:count=33

Cluster

cluster_enabled:0

Keyspace

db0:keys=75515,expires=1780,avg_ttl=5838460898 db5:keys=8,expires=0,avg_ttl=0 db6:keys=90,expires=0,avg_ttl=0

------ CLIENT LIST OUTPUT ------ id=154 addr=172.16.183.135:44085 laddr=172.16.183.139:6379 fd=7 name=redisinsight-cli-30f24486 age=64 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=73 qbuf-free=40881 argv-mem=32 obl=0 oll=0 omem=0 tot-mem=61520 events=r cmd=exhset user=default redir=-1 id=155 addr=172.16.183.135:44087 laddr=172.16.183.139:6379 fd=9 name=redisinsight-browser-b425b0be age=64 idle=64 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20512 events=r cmd=client user=default redir=-1 id=11 addr=172.16.183.135:44083 laddr=172.16.183.139:6379 fd=10 name=120.55.39.163@10006 age=65 idle=5 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=0 qbuf-free=0 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20496 events=r cmd=ping user=default redir=-1

------ CURRENT CLIENT INFO ------ id=154 addr=172.16.183.135:44085 laddr=172.16.183.139:6379 fd=7 name=redisinsight-cli-30f24486 age=64 idle=0 flags=N db=0 sub=0 psub=0 multi=-1 qbuf=73 qbuf-free=40881 argv-mem=32 obl=0 oll=0 omem=0 tot-mem=61520 events=r cmd=exhset user=default redir=-1 argv[0]: 'exhset' argv[1]: 'rroom_demotion' argv[2]: '1049_1' argv[3]: 'abc' argv[4]: 'EX' argv[5]: '0' 20232:M 19 Jun 2023 17:16:19.486 # key 'rroom_demotion' found in DB containing the following object: 20232:M 19 Jun 2023 17:16:19.486 # Object type: 5 20232:M 19 Jun 2023 17:16:19.486 # Object encoding: 0 20232:M 19 Jun 2023 17:16:19.486 # Object refcount: 1

------ MODULES INFO OUTPUT ------

search_version

search_version:2.6.10 search_redis_version:6.2.12 - oss

search_index

search_number_of_indexes:0

search_fields_statistics

search_dialect_statistics

search_dialect_1:0 search_dialect_2:0 search_dialect_3:0

search_runtime_configurations

search_concurrent_mode:OFF search_enableGC:ON search_minimal_term_prefix:2 search_maximal_prefix_expansions:200 search_query_timeout_ms:500 search_timeout_policy:return search_cursor_read_size:1000 search_cursor_max_idle_time:300000 search_max_doc_table_size:1000000 search_max_search_results:1000000 search_max_aggregate_results:-1 search_search_pool_size:20 search_index_pool_size:8 search_gc_scan_size:100 search_min_phonetic_term_length:3

------ FAST MEMORY TEST ------ 20232:M 19 Jun 2023 17:16:19.486 # Bio thread for job type #0 terminated 20232:M 19 Jun 2023 17:16:19.486 # Bio thread for job type #1 terminated 20232:M 19 Jun 2023 17:16:19.486 # Bio thread for job type #2 terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140651036468992) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140651028076288) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140651019683584) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140651011290880) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140651002898176) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140650994505472) terminated 20232:M 19 Jun 2023 17:16:19.486 # IO thread(tid:140650986112768) terminated Preparing to test memory region 5f8000 (446464 bytes) Preparing to test memory region 10fa000 (135168 bytes) Preparing to test memory region 111b000 (135168 bytes) Preparing to test memory region 7febd4f00000 (95420416 bytes) Preparing to test memory region 7febdab07000 (6291456 bytes) Preparing to test memory region 7febdb108000 (8388608 bytes) Preparing to test memory region 7febdb909000 (8388608 bytes) Preparing to test memory region 7febdc10a000 (8388608 bytes) Preparing to test memory region 7febdc90b000 (8388608 bytes) Preparing to test memory region 7febdd10c000 (8388608 bytes) Preparing to test memory region 7febe0913000 (8388608 bytes) Preparing to test memory region 7febe1114000 (8388608 bytes) Preparing to test memory region 7febe1fb7000 (24576 bytes) Preparing to test memory region 7febe1fbd000 (9437184 bytes) Preparing to test memory region 7febe8e00000 (4194304 bytes) Preparing to test memory region 7febe9713000 (20480 bytes) Preparing to test memory region 7febe9930000 (16384 bytes) Preparing to test memory region 7febea250000 (4096 bytes) Preparing to test memory region 7febea251000 (20480 bytes) Preparing to test memory region 7febea261000 (4096 bytes) Preparing to test memory region 7febea262000 (4096 bytes) Preparing to test memory region 7febea265000 (4096 bytes) .O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O.O Fast memory test PASSED, however your memory can still be broken. Please run a memory test for several hours if possible.

sndwow commented 1 year ago

使用的是release-v1.0.0-20230215版本,已经确定为tairHash导致的崩溃

sndwow commented 1 year ago

复现方式为:exhset room key abc EX 0 部分场景下有过期时间为0的情况,该命令被多次执行的时候redis崩溃

sndwow commented 1 year ago

再次每次测试之后发现,并非 EX 0 的时候才会出现,有时候其他情况也会出现,比如EX 120 或者 EX 50。 测试的场景是频繁接口请求去设置更改某个field的内容和EX值

chenyang8094 commented 1 year ago

再次每次测试之后发现,并非 EX 0 的时候才会出现,有时候其他情况也会出现,比如EX 120 或者 EX 50。 测试的场景是频繁接口请求去设置更改某个field的内容和EX值

你好,请问你用的是什么模式?还有,你是否开启了coredump,有的话把coredump信息也贴一下。