search

erthink / libmdbx

One of the fastest embeddable key-value ACID database without WAL. libmdbx surpasses the legendary LMDB in terms of reliability, features and performance.
https://erthink.github.io/libmdbx/
Other
1.16k stars 111 forks source link

MDBX_TXN_FULL - when delete much DupSort data #186

Closed AskAlexSharov closed 3 years ago

AskAlexSharov commented 3 years ago

LMDB has same problem, from lmdb docs:

our estimate of the txn size could be too small. Currently this
 seems unlikely, except with a large number of #MDB_MULTIPLE items.

I guess it's because lmdb doesn't maintain DupSort statistic (amount of pages, entries, etc...), but MDBX does.

Env flags: NoReadahead | Coalesce | Durable Settings: OptSpillMinDenominator=8 OptTxnDpInitial=41024 OptDpReverseLimit=41024 OptTxnDpLimit=128*1024

Pseudocode:

for cursor.Get(prefix, nil, SetRange); !NotFound; curor.Get(nil, nil, NextNoDup) { 
      cursor.Del(NoDupData)
}
erthink commented 3 years ago

I think I can fix it today, or at least give some workaround. Can you provide additional information:

  1. Basic statistics about the table being deleted (the number of elements and pages), i.e. the mdbx_dbi_stat() results.
  2. Transaction information (i.e. the mdbx_txn_info() results) before any deletions from a particular table and immediately before (or near to) the failed deletion.
erthink commented 3 years ago

Also please provide an information about the error you see through the logger, i.e. by means mdbx_setup_debug(). Such logging is done in all cases of this error, except for one (fixed by the commit above). So in any case, this will allow us to understand exactly what is happening in your case.

AskAlexSharov commented 3 years ago

So, looks like I was wrong in pseudocode. Error happening when update/delete keys which DON'T have duplicate values from Dupsort DBI (by historical reasons we do store in Dupsort DBI 2 type of keys - one has duplicate values, another type never has duplicated value. And changes list in this place is not sorted): 

for k,v = in changes {
   if v == nil {
       found = cursor.Get(k, nil, Set)
       if found { 
             cursor.Del(Current)
       }
       continue
   }

   exists = cursor.Put(k, v, NoOverwrite)
    if exists {
         cursor.Put(k, v, Current)
    }
}

Logs before error:

...
INFO [04-22|06:18:03.395] [5/14 Execution] updating accounts
acc stat: updated values 52250, updated values bytes 17279, deleted keys 585652
INFO [04-22|06:18:08.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7170724 space_dirty_kb=484924 space_leftover_kb=39364
INFO [04-22|06:18:08.390] [5/14 Execution] updating accounts
acc stat: updated values 52641, updated values bytes 17408, deleted keys 589992
INFO [04-22|06:18:13.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7172880 space_dirty_kb=487080 space_leftover_kb=37208
INFO [04-22|06:18:13.381] [5/14 Execution] updating accounts
acc stat: updated values 53010, updated values bytes 17546, deleted keys 594296
INFO [04-22|06:18:18.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7175020 space_dirty_kb=489220 space_leftover_kb=35068
INFO [04-22|06:18:18.382] [5/14 Execution] updating accounts
acc stat: updated values 53389, updated values bytes 17672, deleted keys 598377
INFO [04-22|06:18:23.392] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7177112 space_dirty_kb=491312 space_leftover_kb=32976
INFO [04-22|06:18:23.392] [5/14 Execution] updating accounts
acc stat: updated values 53754, updated values bytes 17817, deleted keys 602682
INFO [04-22|06:18:28.393] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7179200 space_dirty_kb=493404 space_leftover_kb=30884
INFO [04-22|06:18:28.393] [5/14 Execution] updating accounts
acc stat: updated values 54139, updated values bytes 17943, deleted keys 606865
INFO [04-22|06:18:33.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7181320 space_dirty_kb=495524 space_leftover_kb=28764
INFO [04-22|06:18:33.386] [5/14 Execution] updating accounts
acc stat: updated values 54554, updated values bytes 18048, deleted keys 611566
INFO [04-22|06:18:38.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7183516 space_dirty_kb=497720 space_leftover_kb=26568
INFO [04-22|06:18:38.384] [5/14 Execution] updating accounts
acc stat: updated values 54930, updated values bytes 18168, deleted keys 615753
INFO [04-22|06:18:43.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7185588 space_dirty_kb=499792 space_leftover_kb=24496
INFO [04-22|06:18:43.384] [5/14 Execution] updating accounts
acc stat: updated values 55320, updated values bytes 18284, deleted keys 620081
INFO [04-22|06:18:48.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7187708 space_dirty_kb=501912 space_leftover_kb=22376
INFO [04-22|06:18:48.391] [5/14 Execution] updating accounts
acc stat: updated values 55694, updated values bytes 18402, deleted keys 624160
INFO [04-22|06:18:53.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7189752 space_dirty_kb=503956 space_leftover_kb=20332
INFO [04-22|06:18:53.391] [5/14 Execution] updating accounts
acc stat: updated values 56063, updated values bytes 18527, deleted keys 628128
INFO [04-22|06:18:58.385] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7191768 space_dirty_kb=505972 space_leftover_kb=18316
INFO [04-22|06:18:58.385] [5/14 Execution] updating accounts
acc stat: updated values 56438, updated values bytes 18652, deleted keys 632421
INFO [04-22|06:19:03.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7193736 space_dirty_kb=507940 space_leftover_kb=16348
INFO [04-22|06:19:03.384] [5/14 Execution] updating accounts
acc stat: updated values 56793, updated values bytes 18783, deleted keys 636365
INFO [04-22|06:19:08.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7195732 space_dirty_kb=509936 space_leftover_kb=14352
INFO [04-22|06:19:08.390] [5/14 Execution] updating accounts
acc stat: updated values 57165, updated values bytes 18893, deleted keys 640458
INFO [04-22|06:19:13.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7197688 space_dirty_kb=511892 space_leftover_kb=12396
INFO [04-22|06:19:13.382] [5/14 Execution] updating accounts
acc stat: updated values 57537, updated values bytes 19002, deleted keys 644577
INFO [04-22|06:19:18.380] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7199636 space_dirty_kb=513840 space_leftover_kb=10448
INFO [04-22|06:19:18.380] [5/14 Execution] updating accounts
acc stat: updated values 57880, updated values bytes 19129, deleted keys 648330
INFO [04-22|06:19:23.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7201544 space_dirty_kb=515748 space_leftover_kb=8540
INFO [04-22|06:19:23.390] [5/14 Execution] updating accounts
acc stat: updated values 58249, updated values bytes 19235, deleted keys 652402
INFO [04-22|06:19:28.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7203500 space_dirty_kb=517704 space_leftover_kb=6584
INFO [04-22|06:19:28.391] [5/14 Execution] updating accounts
acc stat: updated values 58594, updated values bytes 19345, deleted keys 656347
INFO [04-22|06:19:33.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7205388 space_dirty_kb=519592 space_leftover_kb=4696
INFO [04-22|06:19:33.387] [5/14 Execution] updating accounts
acc stat: updated values 58956, updated values bytes 19447, deleted keys 660324
INFO [04-22|06:19:38.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7207288 space_dirty_kb=521492 space_leftover_kb=2796
INFO [04-22|06:19:38.382] [5/14 Execution] updating accounts
acc stat: updated values 59268, updated values bytes 19574, deleted keys 663887
INFO [04-22|06:19:43.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7209040 space_dirty_kb=523244 space_leftover_kb=1044
INFO [04-22|06:19:43.386] [5/14 Execution] updating accounts
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 44 dirty-room, need 45)
acc stat: updated values 59582, updated values bytes 19683, deleted keys 667374
INFO [04-22|06:19:48.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7210796 space_dirty_kb=459488 space_leftover_kb=64800
INFO [04-22|06:19:48.382] [5/14 Execution] updating accounts
acc stat: updated values 59915, updated values bytes 19794, deleted keys 671137
INFO [04-22|06:19:53.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7212604 space_dirty_kb=461296 space_leftover_kb=62992
INFO [04-22|06:19:53.381] [5/14 Execution] updating accounts
acc stat: updated values 60249, updated values bytes 19905, deleted keys 674942
INFO [04-22|06:19:58.383] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7214384 space_dirty_kb=463076 space_leftover_kb=61212
INFO [04-22|06:19:58.383] [5/14 Execution] updating accounts
acc stat: updated values 60587, updated values bytes 20016, deleted keys 678657
INFO [04-22|06:20:03.383] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7216168 space_dirty_kb=464860 space_leftover_kb=59428
INFO [04-22|06:20:03.383] [5/14 Execution] updating accounts
acc stat: updated values 60941, updated values bytes 20124, deleted keys 682717
INFO [04-22|06:20:08.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7218012 space_dirty_kb=466704 space_leftover_kb=57584
INFO [04-22|06:20:08.386] [5/14 Execution] updating accounts
acc stat: updated values 61264, updated values bytes 20232, deleted keys 686259
INFO [04-22|06:20:13.383] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7219816 space_dirty_kb=468508 space_leftover_kb=55780
INFO [04-22|06:20:13.383] [5/14 Execution] updating accounts
acc stat: updated values 61583, updated values bytes 20353, deleted keys 689801
INFO [04-22|06:20:18.389] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7221584 space_dirty_kb=470276 space_leftover_kb=54012
INFO [04-22|06:20:18.389] [5/14 Execution] updating accounts
acc stat: updated values 61901, updated values bytes 20467, deleted keys 693475
INFO [04-22|06:20:23.389] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7223348 space_dirty_kb=472040 space_leftover_kb=52248
INFO [04-22|06:20:23.389] [5/14 Execution] updating accounts
acc stat: updated values 62243, updated values bytes 20583, deleted keys 697256
INFO [04-22|06:20:28.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7225124 space_dirty_kb=473816 space_leftover_kb=50472
INFO [04-22|06:20:28.381] [5/14 Execution] updating accounts
acc stat: updated values 62602, updated values bytes 20684, deleted keys 701321
INFO [04-22|06:20:33.388] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7226968 space_dirty_kb=475660 space_leftover_kb=48628
INFO [04-22|06:20:33.388] [5/14 Execution] updating accounts
acc stat: updated values 62936, updated values bytes 20795, deleted keys 705117
INFO [04-22|06:20:38.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7228744 space_dirty_kb=477436 space_leftover_kb=46852
INFO [04-22|06:20:38.391] [5/14 Execution] updating accounts
acc stat: updated values 63292, updated values bytes 20895, deleted keys 709156
INFO [04-22|06:20:43.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7230556 space_dirty_kb=479248 space_leftover_kb=45040
INFO [04-22|06:20:43.391] [5/14 Execution] updating accounts
acc stat: updated values 63618, updated values bytes 21001, deleted keys 712803
INFO [04-22|06:20:48.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7232308 space_dirty_kb=481004 space_leftover_kb=43284
INFO [04-22|06:20:48.390] [5/14 Execution] updating accounts
acc stat: updated values 63953, updated values bytes 21105, deleted keys 716491
INFO [04-22|06:20:53.380] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7234036 space_dirty_kb=482736 space_leftover_kb=41552
INFO [04-22|06:20:53.380] [5/14 Execution] updating accounts
acc stat: updated values 64272, updated values bytes 21214, deleted keys 720302
INFO [04-22|06:20:58.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7235740 space_dirty_kb=484440 space_leftover_kb=39848
INFO [04-22|06:20:58.391] [5/14 Execution] updating accounts
acc stat: updated values 64589, updated values bytes 21331, deleted keys 723802
INFO [04-22|06:21:03.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7237460 space_dirty_kb=486160 space_leftover_kb=38128
INFO [04-22|06:21:03.381] [5/14 Execution] updating accounts
acc stat: updated values 64914, updated values bytes 21437, deleted keys 727440
INFO [04-22|06:21:08.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7239168 space_dirty_kb=487868 space_leftover_kb=36420
INFO [04-22|06:21:08.390] [5/14 Execution] updating accounts
acc stat: updated values 65251, updated values bytes 21532, deleted keys 731464
INFO [04-22|06:21:13.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7240868 space_dirty_kb=489568 space_leftover_kb=34720
INFO [04-22|06:21:13.386] [5/14 Execution] updating accounts
acc stat: updated values 65581, updated values bytes 21637, deleted keys 735041
INFO [04-22|06:21:18.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7242536 space_dirty_kb=491236 space_leftover_kb=33052
INFO [04-22|06:21:18.382] [5/14 Execution] updating accounts
acc stat: updated values 65881, updated values bytes 21749, deleted keys 738319
INFO [04-22|06:21:23.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7244212 space_dirty_kb=492912 space_leftover_kb=31376
INFO [04-22|06:21:23.386] [5/14 Execution] updating accounts
acc stat: updated values 66216, updated values bytes 21846, deleted keys 741986
INFO [04-22|06:21:28.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7245900 space_dirty_kb=494600 space_leftover_kb=29688
INFO [04-22|06:21:28.384] [5/14 Execution] updating accounts
acc stat: updated values 66541, updated values bytes 21949, deleted keys 745735
INFO [04-22|06:21:33.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7247576 space_dirty_kb=496276 space_leftover_kb=28012
INFO [04-22|06:21:33.381] [5/14 Execution] updating accounts
acc stat: updated values 66851, updated values bytes 22054, deleted keys 749135
INFO [04-22|06:21:38.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7249184 space_dirty_kb=497884 space_leftover_kb=26404
INFO [04-22|06:21:38.390] [5/14 Execution] updating accounts
acc stat: updated values 67174, updated values bytes 22154, deleted keys 752679
INFO [04-22|06:21:43.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7250856 space_dirty_kb=499556 space_leftover_kb=24732
INFO [04-22|06:21:43.386] [5/14 Execution] updating accounts
acc stat: updated values 67503, updated values bytes 22252, deleted keys 756352
INFO [04-22|06:21:48.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7252504 space_dirty_kb=501204 space_leftover_kb=23084
INFO [04-22|06:21:48.386] [5/14 Execution] updating accounts
acc stat: updated values 67819, updated values bytes 22362, deleted keys 759758
INFO [04-22|06:21:53.388] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7254092 space_dirty_kb=502792 space_leftover_kb=21496
INFO [04-22|06:21:53.388] [5/14 Execution] updating accounts
acc stat: updated values 68117, updated values bytes 22463, deleted keys 763288
INFO [04-22|06:21:58.392] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7255716 space_dirty_kb=504416 space_leftover_kb=19872
INFO [04-22|06:21:58.392] [5/14 Execution] updating accounts
acc stat: updated values 68416, updated values bytes 22576, deleted keys 766607
INFO [04-22|06:22:03.399] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7257268 space_dirty_kb=505968 space_leftover_kb=18320
INFO [04-22|06:22:03.399] [5/14 Execution] updating accounts
acc stat: updated values 68708, updated values bytes 22689, deleted keys 769899
INFO [04-22|06:22:08.398] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7258852 space_dirty_kb=507552 space_leftover_kb=16736
INFO [04-22|06:22:08.398] [5/14 Execution] updating accounts
acc stat: updated values 69000, updated values bytes 22796, deleted keys 773192
INFO [04-22|06:22:13.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7260404 space_dirty_kb=509104 space_leftover_kb=15184
INFO [04-22|06:22:13.381] [5/14 Execution] updating accounts
acc stat: updated values 69280, updated values bytes 22899, deleted keys 776396
INFO [04-22|06:22:18.388] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7261932 space_dirty_kb=510632 space_leftover_kb=13656
INFO [04-22|06:22:18.388] [5/14 Execution] updating accounts
acc stat: updated values 69581, updated values bytes 22999, deleted keys 779785
INFO [04-22|06:22:23.380] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7263492 space_dirty_kb=512192 space_leftover_kb=12096
INFO [04-22|06:22:23.380] [5/14 Execution] updating accounts
acc stat: updated values 69870, updated values bytes 23102, deleted keys 782956
INFO [04-22|06:22:28.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7265044 space_dirty_kb=513744 space_leftover_kb=10544
INFO [04-22|06:22:28.391] [5/14 Execution] updating accounts
acc stat: updated values 70162, updated values bytes 23199, deleted keys 786241
INFO [04-22|06:22:33.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7266560 space_dirty_kb=515260 space_leftover_kb=9028
INFO [04-22|06:22:33.387] [5/14 Execution] updating accounts
acc stat: updated values 70461, updated values bytes 23297, deleted keys 789460
INFO [04-22|06:22:38.391] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7268116 space_dirty_kb=516816 space_leftover_kb=7472
INFO [04-22|06:22:38.391] [5/14 Execution] updating accounts
acc stat: updated values 70748, updated values bytes 23399, deleted keys 792668
INFO [04-22|06:22:43.397] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7269636 space_dirty_kb=518336 space_leftover_kb=5952
INFO [04-22|06:22:43.397] [5/14 Execution] updating accounts
acc stat: updated values 71032, updated values bytes 23500, deleted keys 795908
INFO [04-22|06:22:48.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7271148 space_dirty_kb=519848 space_leftover_kb=4440
INFO [04-22|06:22:48.387] [5/14 Execution] updating accounts
acc stat: updated values 71339, updated values bytes 23594, deleted keys 799364
INFO [04-22|06:22:53.407] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7272692 space_dirty_kb=521392 space_leftover_kb=2896
INFO [04-22|06:22:53.407] [5/14 Execution] updating accounts
acc stat: updated values 71650, updated values bytes 23676, deleted keys 802846
INFO [04-22|06:22:58.393] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7274240 space_dirty_kb=522940 space_leftover_kb=1348
INFO [04-22|06:22:58.393] [5/14 Execution] updating accounts
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 44 dirty-room, need 45)
acc stat: updated values 71922, updated values bytes 23773, deleted keys 805737
INFO [04-22|06:23:03.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7275660 space_dirty_kb=474968 space_leftover_kb=49320
INFO [04-22|06:23:03.387] [5/14 Execution] updating accounts
acc stat: updated values 72193, updated values bytes 23873, deleted keys 808761
INFO [04-22|06:23:08.399] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7277148 space_dirty_kb=476456 space_leftover_kb=47832
INFO [04-22|06:23:08.399] [5/14 Execution] updating accounts
acc stat: updated values 72462, updated values bytes 23979, deleted keys 811794
INFO [04-22|06:23:13.380] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7278572 space_dirty_kb=477880 space_leftover_kb=46408
INFO [04-22|06:23:13.380] [5/14 Execution] updating accounts
acc stat: updated values 72769, updated values bytes 24065, deleted keys 815273
INFO [04-22|06:23:18.396] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7280092 space_dirty_kb=479400 space_leftover_kb=44888
INFO [04-22|06:23:18.396] [5/14 Execution] updating accounts
acc stat: updated values 73051, updated values bytes 24164, deleted keys 818404
INFO [04-22|06:23:23.388] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7281564 space_dirty_kb=480872 space_leftover_kb=43416
INFO [04-22|06:23:23.388] [5/14 Execution] updating accounts
acc stat: updated values 73344, updated values bytes 24253, deleted keys 821703
INFO [04-22|06:23:28.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7283048 space_dirty_kb=482356 space_leftover_kb=41932
INFO [04-22|06:23:28.386] [5/14 Execution] updating accounts
acc stat: updated values 73621, updated values bytes 24346, deleted keys 824963
INFO [04-22|06:23:33.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7284532 space_dirty_kb=483840 space_leftover_kb=40448
INFO [04-22|06:23:33.387] [5/14 Execution] updating accounts
acc stat: updated values 73866, updated values bytes 24454, deleted keys 827662
INFO [04-22|06:23:38.389] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7285968 space_dirty_kb=485276 space_leftover_kb=39012
INFO [04-22|06:23:38.389] [5/14 Execution] updating accounts
acc stat: updated values 74138, updated values bytes 24557, deleted keys 830720
INFO [04-22|06:23:43.394] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7287396 space_dirty_kb=486708 space_leftover_kb=37580
INFO [04-22|06:23:43.394] [5/14 Execution] updating accounts
acc stat: updated values 74417, updated values bytes 24659, deleted keys 833826
INFO [04-22|06:23:48.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7288856 space_dirty_kb=488172 space_leftover_kb=36116
INFO [04-22|06:23:48.387] [5/14 Execution] updating accounts
acc stat: updated values 74691, updated values bytes 24757, deleted keys 837020
INFO [04-22|06:23:53.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7290320 space_dirty_kb=489636 space_leftover_kb=34652
INFO [04-22|06:23:53.384] [5/14 Execution] updating accounts
acc stat: updated values 74968, updated values bytes 24859, deleted keys 840151
INFO [04-22|06:23:58.401] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7291768 space_dirty_kb=491084 space_leftover_kb=33204
INFO [04-22|06:23:58.401] [5/14 Execution] updating accounts
acc stat: updated values 75210, updated values bytes 24968, deleted keys 842869
INFO [04-22|06:24:03.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7293136 space_dirty_kb=492452 space_leftover_kb=31836
INFO [04-22|06:24:03.381] [5/14 Execution] updating accounts
acc stat: updated values 75492, updated values bytes 25060, deleted keys 846044
INFO [04-22|06:24:08.397] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7294588 space_dirty_kb=493904 space_leftover_kb=30384
INFO [04-22|06:24:08.397] [5/14 Execution] updating accounts
acc stat: updated values 75765, updated values bytes 25155, deleted keys 849152
INFO [04-22|06:24:13.395] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7295988 space_dirty_kb=495304 space_leftover_kb=28984
INFO [04-22|06:24:13.395] [5/14 Execution] updating accounts
acc stat: updated values 76028, updated values bytes 25253, deleted keys 852140
INFO [04-22|06:24:18.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7297376 space_dirty_kb=496692 space_leftover_kb=27596
INFO [04-22|06:24:18.384] [5/14 Execution] updating accounts
acc stat: updated values 76296, updated values bytes 25349, deleted keys 855187
INFO [04-22|06:24:23.394] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7298784 space_dirty_kb=498104 space_leftover_kb=26184
INFO [04-22|06:24:23.394] [5/14 Execution] updating accounts
acc stat: updated values 76555, updated values bytes 25452, deleted keys 858160
INFO [04-22|06:24:28.381] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7300176 space_dirty_kb=499496 space_leftover_kb=24792
INFO [04-22|06:24:28.382] [5/14 Execution] updating accounts
acc stat: updated values 76802, updated values bytes 25557, deleted keys 860859
INFO [04-22|06:24:33.389] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7301552 space_dirty_kb=500872 space_leftover_kb=23416
INFO [04-22|06:24:33.389] [5/14 Execution] updating accounts
acc stat: updated values 77087, updated values bytes 25645, deleted keys 864140
INFO [04-22|06:24:38.390] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7302992 space_dirty_kb=502312 space_leftover_kb=21976
INFO [04-22|06:24:38.391] [5/14 Execution] updating accounts
acc stat: updated values 77364, updated values bytes 25739, deleted keys 867237
INFO [04-22|06:24:43.385] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7304408 space_dirty_kb=503728 space_leftover_kb=20560
INFO [04-22|06:24:43.385] [5/14 Execution] updating accounts
acc stat: updated values 77657, updated values bytes 25826, deleted keys 870538
INFO [04-22|06:24:48.380] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7305836 space_dirty_kb=505156 space_leftover_kb=19132
INFO [04-22|06:24:48.381] [5/14 Execution] updating accounts
acc stat: updated values 77918, updated values bytes 25921, deleted keys 873441
INFO [04-22|06:24:53.387] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7307232 space_dirty_kb=506552 space_leftover_kb=17736
INFO [04-22|06:24:53.387] [5/14 Execution] updating accounts
acc stat: updated values 78193, updated values bytes 26012, deleted keys 876587
INFO [04-22|06:24:58.392] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7308656 space_dirty_kb=507976 space_leftover_kb=16312
INFO [04-22|06:24:58.392] [5/14 Execution] updating accounts
acc stat: updated values 78444, updated values bytes 26114, deleted keys 879390
INFO [04-22|06:25:03.383] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7309988 space_dirty_kb=509308 space_leftover_kb=14980
INFO [04-22|06:25:03.383] [5/14 Execution] updating accounts
acc stat: updated values 78704, updated values bytes 26213, deleted keys 882291
INFO [04-22|06:25:08.388] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7311336 space_dirty_kb=510660 space_leftover_kb=13628
INFO [04-22|06:25:08.388] [5/14 Execution] updating accounts
acc stat: updated values 78996, updated values bytes 26294, deleted keys 885671
INFO [04-22|06:25:13.384] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7312704 space_dirty_kb=512028 space_leftover_kb=12260
INFO [04-22|06:25:13.384] [5/14 Execution] updating accounts
acc stat: updated values 79270, updated values bytes 26376, deleted keys 888750
INFO [04-22|06:25:18.395] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7314080 space_dirty_kb=513404 space_leftover_kb=10884
INFO [04-22|06:25:18.395] [5/14 Execution] updating accounts
acc stat: updated values 79524, updated values bytes 26465, deleted keys 891589
INFO [04-22|06:25:23.396] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7315388 space_dirty_kb=514712 space_leftover_kb=9576
INFO [04-22|06:25:23.396] [5/14 Execution] updating accounts
acc stat: updated values 79772, updated values bytes 26559, deleted keys 894405
INFO [04-22|06:25:28.395] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7316692 space_dirty_kb=516016 space_leftover_kb=8272
INFO [04-22|06:25:28.395] [5/14 Execution] updating accounts
acc stat: updated values 80047, updated values bytes 26642, deleted keys 897507
INFO [04-22|06:25:33.383] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7318012 space_dirty_kb=517336 space_leftover_kb=6952
INFO [04-22|06:25:33.383] [5/14 Execution] updating accounts
acc stat: updated values 80318, updated values bytes 26720, deleted keys 900422
INFO [04-22|06:25:38.386] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7319324 space_dirty_kb=518648 space_leftover_kb=5640
INFO [04-22|06:25:38.386] [5/14 Execution] updating accounts
acc stat: updated values 80589, updated values bytes 26811, deleted keys 903405
INFO [04-22|06:25:43.382] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7320652 space_dirty_kb=519976 space_leftover_kb=4312
INFO [04-22|06:25:43.382] [5/14 Execution] updating accounts
acc stat: updated values 80831, updated values bytes 26902, deleted keys 906179
INFO [04-22|06:25:48.397] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7321968 space_dirty_kb=521296 space_leftover_kb=2992
INFO [04-22|06:25:48.397] [5/14 Execution] updating accounts
acc stat: updated values 81107, updated values bytes 26980, deleted keys 909342
INFO [04-22|06:25:53.399] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7323308 space_dirty_kb=522636 space_leftover_kb=1652
INFO [04-22|06:25:53.399] [5/14 Execution] updating accounts
acc stat: updated values 81358, updated values bytes 27066, deleted keys 912209
INFO [04-22|06:25:58.393] Tx info                                  id=77942 read_lag=0 ro=false space_retired_kb=7324616 space_dirty_kb=523944 space_leftover_kb=344
INFO [04-22|06:25:58.393] [5/14 Execution] updating accounts
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 44 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 44 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 43 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 42 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16378 dirty-entries (have 41 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 40 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 39 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 37 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 37 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 36 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 35 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 34 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16379 dirty-entries (have 33 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 32 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 32 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 31 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 30 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 29 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 28 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 27 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16380 dirty-entries (have 25 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 24 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 23 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 22 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 21 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 20 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 19 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 18 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16381 dirty-entries (have 17 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 16 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 15 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 14 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 13 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 12 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 11 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 10 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16382 dirty-entries (have 9 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 8 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 7 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 6 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 5 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 4 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 3 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 2 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16383 dirty-entries (have 1 dirty-room, need 45)
mdbx_txn_spill:8171 spilling 16384 dirty-entries (have 0 dirty-room, need 45)
mdbx_page_alloc:9479 Dirtyroom is depleted, DPL length 131072
ERROR[04-22|06:27:58.924] Error                                    err="[5/14 Execution] update plain account: mdbx_cursor_put: MDBX_TXN_FULL: Transaction has too many dirty pages, i.e transaction is too big"
erthink commented 3 years ago

There seems to be a regression in the page-spilling code.

erthink commented 3 years ago

The problem was very difficult to reproduce. This is not a regression, so I need to think about how best to fix it.

erthink commented 3 years ago

The problem is that historically MDBX/LMDB are not designed for huge transactions. Including page spilling is implemented without LRU, but just the tail of dirty pages list. Therefore, there may be situations where most of the spilled pages almost immediately need to be lifted into memory. I.e. a newly freed space in the dirty pages list becomes almost full again, which leads to error.

In your case, this problem is visible with the MDBX and invisible with the LMDB, since in the MDBX case a significantly smaller limit (OptTxnDpLimit) is set for the size of the dirty page list than the hardcoded in the LMDB. Therefore a workaround is simple - just increase the OptTxnDpLimit.

Nonetheless, I will try to implement spilling using LRU and finding adjacent pages (to make writing to disk more sequentially). In usecases with a huge transactions, a large database, and a lack of RAM, this should bring performance closer to MDBX_WRITEMAP mode.

AskAlexSharov commented 3 years ago

I will implement sorting of changes in this place of our app.

erthink commented 3 years ago

Ready for testing.

AskAlexSharov commented 3 years ago

On same scenario (DpLimit=64*1024) - kind of same result: 


mdbx_setup_dxb:14878 open-MADV_DONTNEED 160647678..160956416
mdbx_set_readahead:8982 readahead OFF 0..160647678
INFO [04-27|14:33:43.973] Wrap db to snapshots                     dir=/media/alex/evo/mdbx/tg/snapshot mode=
INFO [04-27|14:33:43.973] Stage4                                   progress=12210900
INFO [04-27|14:33:43.973] [1/14 Headers] Unwind Execution          from=12210900 to=12200900
collected: 94M bytes
collected: 275M bytes
mdbx_find_oldest:8869 update oldest 0 -> 231265
acc stat: updated values 1, updated values bytes 0, deleted keys 10
INFO [04-27|14:33:59.123] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=24 space_dirty_kb=24 space_leftover_kb=262120
INFO [04-27|14:33:59.123] [1/14 Headers] updating accounts
acc stat: updated values 9193, updated values bytes 4741, deleted keys 108379
INFO [04-27|14:34:03.974] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=99864 space_dirty_kb=99864 space_leftover_kb=162280
INFO [04-27|14:34:03.974] [1/14 Headers] updating accounts
acc stat: updated values 13697, updated values bytes 7075, deleted keys 161873
INFO [04-27|14:34:08.974] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=141720 space_dirty_kb=141720 space_leftover_kb=120424
INFO [04-27|14:34:08.974] [1/14 Headers] updating accounts
acc stat: updated values 17269, updated values bytes 8912, deleted keys 204178
INFO [04-27|14:34:13.973] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=172496 space_dirty_kb=172496 space_leftover_kb=89648
INFO [04-27|14:34:13.973] [1/14 Headers] updating accounts
acc stat: updated values 20382, updated values bytes 10469, deleted keys 240980
INFO [04-27|14:34:18.974] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=197876 space_dirty_kb=197876 space_leftover_kb=64268
INFO [04-27|14:34:18.974] [1/14 Headers] updating accounts
acc stat: updated values 23049, updated values bytes 11864, deleted keys 272904
INFO [04-27|14:34:23.975] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=219164 space_dirty_kb=219164 space_leftover_kb=42980
INFO [04-27|14:34:23.975] [1/14 Headers] updating accounts
acc stat: updated values 25335, updated values bytes 13036, deleted keys 300709
INFO [04-27|14:34:28.975] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=236816 space_dirty_kb=236816 space_leftover_kb=25328
INFO [04-27|14:34:28.975] [1/14 Headers] updating accounts
acc stat: updated values 27264, updated values bytes 14034, deleted keys 323493
INFO [04-27|14:34:33.975] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=251328 space_dirty_kb=251328 space_leftover_kb=10816
INFO [04-27|14:34:33.975] [1/14 Headers] updating accounts
mdbx_txn_spill:8392 spilling 8186 dirty-entries (have 43 dirty-room, need 44)
mdbx_txn_spill:8595 spilled 308 dirty-entries, now have 351 dirty-room
mdbx_txn_spill:8392 spilling 8186 dirty-entries (have 43 dirty-room, need 44)
mdbx_txn_spill:8595 spilled 1 dirty-entries, now have 44 dirty-room
mdbx_txn_spill:8392 spilling 8186 dirty-entries (have 42 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 40 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 39 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 38 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 37 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 36 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 35 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8187 dirty-entries (have 33 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 32 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 31 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 30 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 29 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 28 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 27 dirty-room, need 44)
acc stat: updated values 28874, updated values bytes 14890, deleted keys 342688
INFO [04-27|14:34:38.979] Tx info                                  id=231266 read_lag=0 ro=false space_retired_kb=263276 space_dirty_kb=262040 space_leftover_kb=104
INFO [04-27|14:34:38.979] [1/14 Headers] updating accounts
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 26 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8188 dirty-entries (have 25 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 24 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 23 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 22 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 21 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 19 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 18 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8189 dirty-entries (have 17 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 16 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 16 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 15 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 14 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 12 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8190 dirty-entries (have 10 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 8 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 7 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 6 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 5 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 4 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 3 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8191 dirty-entries (have 2 dirty-room, need 44)
mdbx_txn_spill:8392 spilling 8192 dirty-entries (have 0 dirty-room, need 44)
mdbx_page_dirty:8912 Dirtyroom is depleted, DPL length 65536
ERROR[04-27|14:34:49.945] Error                                    err="[1/14 Headers] update plain account: mdbx_cursor_put: MDBX_TXN_FULL: Transaction has too many dirty pages, i.e transaction is too big"
AskAlexSharov commented 3 years ago

Trace: 

mdbx_txn_spill:8475 spilling 8192 dirty-entries (have 0 dirty-room, need 44)
integration: mdbx:8986: mdbx_page_dirty: Assertion `txn->tw.dirtyroom > 0' failed.
SIGABRT: abort
PC=0x7fa22bb3418b m=0 sigcode=18446744073709551610
signal arrived during cgo execution

goroutine 1 [syscall, locked to thread]:
non-Go function
    pc=0x7fe139ad518b
non-Go function
    pc=0x7fe139ab4858
non-Go function
    pc=0x7fe139ab4728
non-Go function
    pc=0x7fe139ac5f35
page_node
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:4031 pc=0x133da31
mdbx_page_split
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:21209 pc=0x133da31
mo_c11_load
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:1934 pc=0x12dae15
atomic_load64
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:2028 pc=0x12dae15
safe64_inc
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:4415 pc=0x12dae15
spill_page
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:8417 pc=0x12dae15
mo_c11_load
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:1934 pc=0x12df5b7
atomic_load64
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:2028 pc=0x12df5b7
mdbx_find_largest
    /home/alex/progects/turbo-geth/ethdb/mdbx/dist/mdbx.c:8969 pc=0x12df5b7
runtime.cgocall(0x1153c21, 0xc007bf2188, 0xc004e10020)
    runtime/cgocall.go:154 +0x5b fp=0xc007bf2130 sp=0xc007bf20f8 pc=0x414cdb
github.com/ledgerwatch/turbo-geth/ethdb/mdbx._Cfunc_mdbxgo_cursor_put2(0x15994b50, 0xc004e94510, 0x14, 0xc004a314f0, 0xe, 0xc000000040, 0x0)
erthink commented 3 years ago

Thanks, but need more frames further the stack, up to your GoLang code.

AskAlexSharov commented 3 years ago

Found root cause: every tx.Put/Del op did open cursor and doesn't close. It caused next issue - each cursor was pointed to own dirty page - dirty pages on which pointed cursor can't spill - in result all dirty pages can't spill -> txn_full

It fixed now.