tarantool / tarantool

Get your data in RAM. Get compute close to data. Enjoy the performance.
https://www.tarantool.io
Other
3.4k stars 379 forks source link

tarantool is crashed: vy_slice_wait_pinned #10094

Closed ligurio closed 4 months ago

ligurio commented 4 months ago

Bug description

Tarantool 3.2.0-entrypoint-56-g05d03a1c58 Target: Linux-x86_64-Debug Build options: cmake . -DCMAKE_INSTALL_PREFIX=/usr/local -DENABLE_BACKTRACE=TRUE Compiler: GNU-11.4.0 C_FLAGS: -fexceptions -funwind-tables -fasynchronous-unwind-tables -fno-common -msse2 -Wformat -Wformat-security -Werror=format-security -fstack-protector-strong -fPIC -fmacro-prefix-map=/home/sergeyb/sources/MRG/tarantool=. -std=c11 -Wall -Wextra -Wno-gnu-alignof-expression -fno-gnu89-inline -Wno-cast-function-type -Werror -g -ggdb -O0 CXX_FLAGS: -fexceptions -funwind-tables -fasynchronous-unwind-tables -fno-common -msse2 -Wformat -Wformat-security -Werror=format-security -fstack-protector-strong -fPIC -fmacro-prefix-map=/home/sergeyb/sources/MRG/tarantool=. -std=c++11 -Wall -Wextra -Wno-invalid-offsetof -Wno-gnu-alignof-expression -Wno-cast-function-type -Werror -g -ggdb -O0

Steps to reproduce

Actually, there are no exact steps to reproduce.

Actual behavior

$ taskset 0xef ./tarantool vinyl.lua --workers 50 --test_duration 10                                         
Random seed: 1717594034                                                                                                                            
CLEANUP                                                                                                                                            
SETUP                                                                                                                                              
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> Tarantool 3.2.0-entrypoint-56-g05d03a1c58 Linux-x86_64-Debug                                
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> log level 5 (INFO)                                                                          
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> wal/engine cleanup is paused                                                                
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> mapping 67108864 bytes for memtx tuple arena...                                             
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> Actual slab_alloc_factor calculated on the basis of desired slab_alloc_factor = 1.044274
2024-06-05 16:27:14.086 [745732] main/104/vinyl.lua I> mapping 16777216 bytes for vinyl tuple arena...
2024-06-05 16:27:14.093 [745732] main/104/vinyl.lua I> update replication_synchro_quorum = 1
2024-06-05 16:27:14.093 [745732] main/104/vinyl.lua I> instance uuid 9da988b4-34aa-4f11-b7f6-ccab9d7d3628
2024-06-05 16:27:14.093 [745732] main/104/vinyl.lua I> initializing an empty data directory
2024-06-05 16:27:14.115 [745732] main/104/vinyl.lua I> assigned id 1 to replica 9da988b4-34aa-4f11-b7f6-ccab9d7d3628
2024-06-05 16:27:14.116 [745732] main/104/vinyl.lua I> update replication_synchro_quorum = 1
2024-06-05 16:27:14.116 [745732] main/104/vinyl.lua I> replicaset uuid 8218517e-5a64-4413-9d7d-9d3ebd1116a0
2024-06-05 16:27:14.117 [745732] snapshot/101/main I> saving snapshot `./00000000000000000000.snap.inprogress'
2024-06-05 16:27:14.128 [745732] snapshot/101/main I> done
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua I> ready to accept requests
2024-06-05 16:27:14.129 [745732] main/105/gc I> wal/engine cleanup is resumed
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'memtx_memory' configuration option to 1048576
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'vinyl_memory' configuration option to 10485760
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'vinyl_cache' configuration option to 9
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'vinyl_timeout' configuration option to 5
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'vinyl_max_tuple_size' configuration option to 40143
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'checkpoint_count' configuration option to 4
2024-06-05 16:27:14.129 [745732] main/104/vinyl.lua/box.load_cfg I> set 'checkpoint_wal_threshold' configuration option to 337
2024-06-05 16:27:14.130 [745732] main/104/vinyl.lua/box.load_cfg I> set 'checkpoint_interval' configuration option to 3
2024-06-05 16:27:14.131 [745732] main/104/vinyl.lua/vinyl I> FINISH BOX.CFG
2024-06-05 16:27:14.131 [745732] main/104/vinyl.lua/vinyl I> CREATE A SPACE
2024-06-05 16:27:14.131 [745732] main/104/vinyl.lua/vinyl I> {"format":[{"name":"name_1","type":"string"},{"name":"name_2","type":"uuid"},{"name":"
name_3","type":"uuid"},{"name":"name_4","type":"decimal"},{"name":"name_5","type":"number"},{"name":"name_6","type":"boolean"}],"if_not_exists":fal
se,"is_local":false,"field_count":0,"engine":"vinyl"}
2024-06-05 16:27:14.131 [745732] main/106/checkpoint_daemon I> scheduled next checkpoint for Wed Jun  5 16:27:18 2024
2024-06-05 16:27:14.139 [745732] main I> WAL threshold exceeded, triggering checkpoint
2024-06-05 16:27:14.142 [745732] main/104/vinyl.lua/vinyl I> FINISH SETUP 
2024-06-05 16:27:14.142 [745732] snapshot/101/main I> saving snapshot `./00000000000000000002.snap.inprogress'
2024-06-05 16:27:14.143 [745732] snapshot/101/main I> done
2024-06-05 16:27:14.158 [745732] main/114/WORKER #1/vinyl I> {"unique":true,"parts":[{"fieldno":1,"sort_order":"asc","type":"string","exclude_null"
:false,"is_nullable":false},{"fieldno":2,"sort_order":"asc","type":"uuid","exclude_null":false,"is_nullable":false},{"fieldno":3,"sort_order":"asc"
,"type":"uuid","exclude_null":false,"is_nullable":false},{"fieldno":4,"sort_order":"asc","type":"decimal","exclude_null":false,"is_nullable":false}
,{"fieldno":5,"sort_order":"asc","type":"number","exclude_null":false,"is_nullable":false},{"fieldno":6,"sort_order":"asc","type":"boolean","exclud
e_null":false,"is_nullable":false}],"options":{"page_size":8192,"run_count_per_level":2,"run_size_ratio":2,"bloom_fpr":0.15},"space_id":512,"type":
"TREE","name":"idx_82","id":0}
2024-06-05 16:27:14.158 [745732] main/114/WORKER #1/vinyl I> {"unique":true,"parts":[{"fieldno":1,"sort_order":"asc","type":"string","exclude_null"
:false,"is_nullable":false},{"fieldno":2,"sort_order":"asc","type":"uuid","exclude_null":false,"is_nullable":false},{"fieldno":3,"sort_order":"asc"
,"type":"uuid","exclude_null":false,"is_nullable":false},{"fieldno":4,"sort_order":"asc","type":"decimal","exclude_null":false,"is_nullable":false}
,{"fieldno":5,"sort_order":"asc","type":"number","exclude_null":false,"is_nullable":false},{"fieldno":6,"sort_order":"asc","type":"boolean","exclud
e_null":false,"is_nullable":false}],"options":{"page_size":8192,"run_count_per_level":2,"run_size_ratio":2,"bloom_fpr":0.15},"space_id":512,"type":
"TREE","name":"idx_82","id":0}

<snipped>

2-8fa2-7713dbcb7ad7","607561182792",806062227739,false]]]                                                                                          
2024-06-05 16:27:14.634 [745732] main/117/WORKER #4/vinyl I> ["INSERT_OP",[["nnnnnnnnnn","64d5690a-d89e-4993-9edb-5ae559efa9eb","60257c79-3162-400d
-8535-89ace8fd4f33","202137389973",793269667050,false]]]                                                                                           
2024-06-05 16:27:14.634 [745732] main/155/WORKER #42/vinyl I> ["REPLACE_OP",[["qqqqqqqqqq","75a4c820-b32d-4cb2-89ec-6d868e8777a1","dc776de4-1357-42
a0-89ce-18bafdab785e","54141138741",916057874952,false]]]                                                                                          
2024-06-05 16:27:14.634 [745732] main/157/WORKER #44/vinyl I> ["REPLACE_OP",[["tttttttttt","40a74db9-adaa-4e93-9d29-44168239a0c4","172a033b-1378-43
59-97f9-bbf2763575ca","950862659139",288766484836,false]]]                                                                                         
2024-06-05 16:27:14.634 [745732] main/159/WORKER #46/vinyl I> ["REPLACE_OP",[["bbbbbbbbbb","5794bedb-0d2b-4343-8e77-44790884a4be","1bf36964-7875-4d
a1-85d5-27926c313663","885679676868",325003711392,true]]]                                                                                          
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39/vinyl I> ["INDEX_DROP_OP",[]]                                                                 
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39 memtx_tx.c:698 W> Transaction committing DDL (id=2118) has aborted another TX (id=2113)       
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39 memtx_tx.c:698 W> Transaction committing DDL (id=2118) has aborted another TX (id=2114)       
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39 memtx_tx.c:698 W> Transaction committing DDL (id=2118) has aborted another TX (id=2115)       
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39 memtx_tx.c:698 W> Transaction committing DDL (id=2118) has aborted another TX (id=2116)       
2024-06-05 16:27:14.634 [745732] main/152/WORKER #39 memtx_tx.c:698 W> Transaction committing DDL (id=2118) has aborted another TX (id=2117)       
2024-06-05 16:27:14.634 [745732] main/123/WORKER #10/vinyl I> ["REPLACE_OP",[["xxxxxxxxxx","84f884a3-44e9-4d94-b667-e03441a57d1a","63d7ae40-5638-47
65-82e7-6a08e899f283","298408426806",286365624709,false]]]                                                                                         
Segmentation fault                                                                                                                                 
  code: SEGV_MAPERR                                                                                                                                
  addr: 0xb0                                                                                                                                       
  context: 0x651b9c373800         
  siginfo: 0x651b9c373930                                                
  rax      0x0                0                                          
  rbx      0x651b9ada7220     111169236529696
  rcx      0x651b9c3e91d0     111169259868624
  rdx      0x3ff0000000000000 4607182418800017408
  rsi      0x7de2bee95ac0     138412819045056
  rdi      0x7de2bee95ac0     138412819045056
  rsp      0x7ffe54124060     140730308903008
  rbp      0x7ffe54124090     140730308903056
  r8       0x651b9a3cb157     111169226191191
  r9       0x651b9a89d07f     111169231245439    
  r10      0x651b9a89d5e9     111169231246825
  r11      0xeee606e0163d09f8 -1232289888523712008
  r12      0x7ffe541248ec     140730308905196 
  r13      0x7ffe54124918     140730308905240       
  r14      0x651b9ad3e660     111169236100704
  r15      0x7de2bf586040     138412826320960
  rip      0x651b9a5ed0e0     111169228427488
  eflags   0x10246            66118                                      
  cs       0x33               51                                         
  gs       0x0                0                                          
  fs       0x0                0                                          
  cr2      0xb0               176                                        
  err      0x4                4                                          
  oldmask  0x0                0                                          
  trapno   0xe                14                                         
Current time: 1717594034
Please file a bug at https://github.com/tarantool/tarantool/issues
Attempting backtrace... Note: since the server has already crashed, 
this may fail as well
#1  0x651b9a5e3098 in crash_collect+256
#2  0x651b9a5e3ad4 in crash_signal_cb+100
#3  0x7de2be242520 in __sigaction+80 
#4  0x651b9a5ed0e0 in cord_reset_slice+263
#5  0x651b9a5ee532 in fiber_yield_impl+262
#6  0x651b9a5ee69e in fiber_yield+18 
#7  0x651b9a5ee90b in fiber_yield_timeout+314
#8  0x651b9a5fb6f7 in fiber_cond_wait_timeout+202
#9  0x651b9a5fb880 in fiber_cond_wait+40
#10 0x651b9a3ca948 in vy_slice_wait_pinned+30
#11 0x651b9a3cb1a1 in vy_range_tree_free_cb+74
#12 0x651b9a3ca1b2 in vy_range_tree_iter_recurse+133
#13 0x651b9a3ca396 in vy_range_tree_iter+98
#14 0x651b9a3cb4d5 in vy_lsm_delete+744
#15 0x651b9a39c672 in vinyl_index_destroy+44
#16 0x651b9a33e62a in index_delete+110
#17 0x651b9a40f4f3 in index_unref+103
#18 0x651b9a41397a in space_delete+188
#19 0x651b9a42dca7 in alter_space_commit(trigger*, void*)+251
#20 0x651b9a6193e6 in trigger_run_list(rlist*, void*)+62
#21 0x651b9a6195d6 in trigger_run_reverse+183
#22 0x651b9a45027e in txn_complete_success+563
#23 0x651b9a450889 in txn_on_journal_writAborted (core dumped)

coredump + tarantool binary: gh-10094-core.zip

Backtrace:

(gdb) bt                                                                                                                                           
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=138412819045056) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_internal (signo=6, threadid=138412819045056) at ./nptl/pthread_kill.c:78
#2  __GI___pthread_kill (threadid=138412819045056, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#3  0x00007de2be242476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26 
#4  0x00007de2be2287f3 in __GI_abort () at ./stdlib/abort.c:79        
#5  0x0000651b9a5e3b7d in crash_signal_cb (signo=11, siginfo=0x651b9c373930, context=0x651b9c373800)
    at /home/sergeyb/sources/MRG/tarantool/src/lib/core/crash.c:203   
#6  <signal handler called>                                                                                                                        
#7  0x0000651b9a5ed0e0 in cord_reset_slice (f=0x0) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber.c:464            
#8  0x0000651b9a5ee532 in fiber_yield_impl (will_switch_back=true) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber.c:846  
#9  0x0000651b9a5ee69e in fiber_yield () at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber.c:869                   
#10 0x0000651b9a5ee90b in fiber_yield_timeout (delay=3153600000) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber.c:913
#11 0x0000651b9a5fb6f7 in fiber_cond_wait_timeout (c=0x7de29c010f98, timeout=3153600000)                                  
    at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber_cond.c:107                                                                           
#12 0x0000651b9a5fb880 in fiber_cond_wait (c=0x7de29c010f98) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/fiber_cond.c:121             
#13 0x0000651b9a3ca948 in vy_slice_wait_pinned (slice=0x7de29c010f60) at /home/sergeyb/sources/MRG/tarantool/src/box/vy_run.h:513
#14 0x0000651b9a3cb1a1 in vy_range_tree_free_cb (t=0x651b9c681ac8, range=0x651b9c619600, arg=0x0)
    at /home/sergeyb/sources/MRG/tarantool/src/box/vy_lsm.c:259       
#15 0x0000651b9a3ca1b2 in vy_range_tree_iter_recurse (rbtree=0x651b9c681ac8, node=0x651b9c619600, cb=0x651b9a3cb157 <vy_range_tree_free_cb>, 
    arg=0x0) at /home/sergeyb/sources/MRG/tarantool/src/box/vy_range.h:173
#16 0x0000651b9a3ca396 in vy_range_tree_iter (rbtree=0x651b9c681ac8, start=0x0, cb=0x651b9a3cb157 <vy_range_tree_free_cb>, arg=0x0)        
    at /home/sergeyb/sources/MRG/tarantool/src/box/vy_range.h:173  
#17 0x0000651b9a3cb4d5 in vy_lsm_delete (lsm=0x651b9c681690) at /home/sergeyb/sources/MRG/tarantool/src/box/vy_lsm.c:292
#18 0x0000651b9a39c672 in vinyl_index_destroy (index=0x651b9c681690) at /home/sergeyb/sources/MRG/tarantool/src/box/vinyl.c:724
#19 0x0000651b9a33e62a in index_delete (index=0x651b9c681690) at /home/sergeyb/sources/MRG/tarantool/src/box/index.cc:810
#20 0x0000651b9a40f4f3 in index_unref (index=0x651b9c681690) at /home/sergeyb/sources/MRG/tarantool/src/box/index.h:813
#21 0x0000651b9a41397a in space_delete (space=0x651b9c598e30) at /home/sergeyb/sources/MRG/tarantool/src/box/space.c:705
#22 0x0000651b9a42dca7 in alter_space_commit (trigger=0x7de2bb3574b0, event=0x7de2bb357290)
--Type <RET> for more, q to quit, c to continue without paging--
    at /home/sergeyb/sources/MRG/tarantool/src/box/alter.cc:895
#23 0x0000651b9a6193e6 in trigger_run_list (list=0x7ffe54124530, event=0x7de2bb357290)
    at /home/sergeyb/sources/MRG/tarantool/src/lib/core/trigger.cc:100
#24 0x0000651b9a6195d6 in trigger_run_reverse (list=0x7de2bb3571a0, event=0x7de2bb357290)
    at /home/sergeyb/sources/MRG/tarantool/src/lib/core/trigger.cc:147
#25 0x0000651b9a45027e in txn_complete_success (txn=0x7de2bb357038) at /home/sergeyb/sources/MRG/tarantool/src/box/txn.c:784
#26 0x0000651b9a450889 in txn_on_journal_write (entry=0x7de2bb357520) at /home/sergeyb/sources/MRG/tarantool/src/box/txn.c:844
#27 0x0000651b9a4b71c6 in journal_async_complete (entry=0x7de2bb357520) at /home/sergeyb/sources/MRG/tarantool/src/box/journal.h:257
#28 0x0000651b9a4b7c55 in tx_schedule_queue (queue=0x7de2bb331920) at /home/sergeyb/sources/MRG/tarantool/src/box/wal.c:284
#29 0x0000651b9a4b7de1 in tx_complete_batch (msg=0x7de2bb331900) at /home/sergeyb/sources/MRG/tarantool/src/box/wal.c:380
#30 0x0000651b9a5f93e8 in cmsg_deliver (msg=0x7de2bb331900) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/cbus.c:350
#31 0x0000651b9a5f9d78 in cbus_process (endpoint=0x651b9ad9ac40 <tx_prio_endpoint>) at /home/sergeyb/sources/MRG/tarantool/src/lib/core/cbus.c:601
#32 0x0000651b9a477b15 in tx_prio_cb (loop=0x651b9ade52a0 <default_loop_struct>, watcher=0x651b9ad9ad90 <tx_prio_endpoint+336>, events=524288)
    at /home/sergeyb/sources/MRG/tarantool/src/box/box.cc:5449
#33 0x0000651b9a9ce39f in ev_invoke_pending (loop=0x651b9ade52a0 <default_loop_struct>)
    at /home/sergeyb/sources/MRG/tarantool/third_party/libev/ev.c:3797
#34 0x0000651b9a9cf345 in ev_run (loop=0x651b9ade52a0 <default_loop_struct>, flags=0)
    at /home/sergeyb/sources/MRG/tarantool/third_party/libev/ev.c:4221
#35 0x0000651b9a5b471a in tarantool_lua_run_script (path=0x651b9c364574 "vinyl.lua", instance=0x651b9ad657f0 <main::instance>, opt_mask=0, 
    optc=0, optv=0x0, argc=5, argv=0x651b9c364538) at /home/sergeyb/sources/MRG/tarantool/src/lua/init.c:1196
#36 0x0000651b9a31fd3f in main (argc=5, argv=0x651b9c364538) at /home/sergeyb/sources/MRG/tarantool/src/main.cc:1057

Expected behavior

no crash

locker commented 4 months ago

Short reproducer:

local fiber = require('fiber')

box.cfg{}

local s = box.schema.create_space('test', {engine = 'vinyl'})
s:create_index('pk')
s:create_index('sk', {parts = {2, 'unsigned'}})
s:insert{1, 10}
box.snapshot()

box.error.injection.set('ERRINJ_VY_READ_PAGE_DELAY', true)
fiber.create(function()
    s:insert{2, 10}
end)
s.index.sk:drop()
box.error.injection.set('ERRINJ_VY_READ_PAGE_DELAY', false)
os.exit(0)

The crash occurs because the index is dropped while another fiber is reading from it. As a result, vy_lsm_delete yields while waiting for the reader to finish, which results in a crash in the alter_space_commit trigger, where yields aren't allowed.

To fix this issue we need to take a reference to the index before yielding on disk. Also, we need to replace vy_slice_wait_pinned(slice) in vy_range_tree_fee_cb with assert(slice->pin_count == 0), because vy_lsm_delete must not yield:

https://github.com/tarantool/tarantool/blob/1f75231a0c0ce062e08660e0bc51485f7086412c/src/box/vy_lsm.c#L252-L262

We already fixed a similar issue, see 75f03a50df4a7.