mdbx_txn_commit_ex: MDBX_KEYEXIST: Key/data pair already exists

[AskAlexSharov]

It's a bit unclear for me - what I can do with MDBX_KEYEXIST inside mdbx_txn_commit_ex
last master: 21d2af9
do you need some additional info?

[erthink]

Hm, I fixed (3fd0792) a similar problem a week ago.
To understand what was going on, I had to add additional logging and run tests on cluster for a weeks.
This problem was only noticed during testing and never showed up during operation due to the complexity of the scenario.

Anyway I need to understand how you managed to provoke this problem.
It is very likely that will also have to enable additional logging with a special patch.

[erthink]

Currently I assume this is a regression since 55d190b and 70241e2 for #123.
I.e the problem only affects your extreme use cases and does not appear in others.
If so, it will be easier to fix the problem, although I still need to think about how to do it without new regressions.

[AskAlexSharov]

For now it happened 2 times: 1 time on small transaction, 1 time on big one.
Env had Lifo flag and small freelist (I didn't test without Lifo flag).
And doesn't reproduce anymore. Let's see if it will reproduce during night tests.

[erthink]

In a few hours (as soon as I get to the computer) I will provide you a patch with additional logging.

It will be great if you add code to collect these logs. This log can be stored in memory, cleared at the start of each transaction, and saved only when an error occurs.

[AskAlexSharov]

ok, i have way to reproduce it: by dropping DBI.
logs - no problem to add.

[erthink]

logging-update-gc.patch

Don't forget to set your logger via mdbx_setup_debug().

[AskAlexSharov]

1.trace.log

1.extra.log

[erthink]

С логами пара проблем:

1. Вы использовали отладочную сборку, в которой логирование включено для всего объема кода. Из-за этого логи получились огромными.
2. В использованной отладочной сборке вы также включили внутренний аудит, и судя по логам это выявило расхождение в кол-ве используемых и выделенных страниц БД. Грубо говоря, аудит посчитал что выявил потерю страниц (нигде не учтенные страницы) и коммит был прерван с возвратом MDBX_PROBLEM раньше чем дело дошло до MDBX_KEYEXIST.

Достаточно маловероятно, что в libmdbx сейчас есть баги приводящие к потере страниц. Исходно даже в LMDB c этим было относительно хорошо, и похоже оставшаяся парочка давно была устранена в libmdbx. Кроме этого, всё это было многократно проверено тестами и практическим использованием в тысячах инсталляций.

А вот с аудитом ситуация обратная - эта внутренняя feature используется только при отладке, в некоторых тестах и "на всякий случай" разбирательстве с проблемами. Т.е. аудит относительно мало обкатан в сравнении с остальным кодом.
Соответственно, похоже что включив аудит вы выявили в нём какой-то логический недочет.

Поэтому для получения логов по исходной проблеме предлагаю использовать обычную сборку libmdbx, но с предложенным выше патчем. А пока вы готовите логи я поразбираюсь с аудитом. Если технически вам удобно использовать отладочную сборку, то всё равно стоит приложить патч, а посредством mdbx_setup_debug(MDBX_LOG_VERBOSE, MDBX_DBG_ASSERT, your_logger) уменьшить объем логов и (временно) отключить аудит.

[AskAlexSharov]

Перестарался. Вот что осталось:

mdbx_setup_dxb:13079 open-MADV_DONTNEED 108364316..108394890
mdbx_set_readahead:7697 readahead OFF 0..108364316
mdbx_find_oldest:7616 update oldest 0 -> 167216

[AskAlexSharov]

А, нет, вот:

check_fstat:26405 lck-file is too short (0), exclusive-lock needed
mdbx_read_header:11788 latch meta[0]
mdbx_read_header:11788 latch meta[1]
mdbx_read_header:11788 latch meta[2]
mdbx_read_header:11788 latch meta[2]
mdbx_setup_dxb:12707 header: root 3/108361938, geo 3/108364316-108364316/536870912 +65535 -1, txn_id 167217, Steady
mdbx_setup_dxb:12833 current boot-id 8254ba6238386bb6-99e6df91350c4905 (available)
mdbx_set_readahead:7697 readahead OFF 0..108364316
mdbx_find_oldest:7616 update oldest 0 -> 167217
mdbx_page_alloc:8485 try growth datafile to 108394890 pages (+30574)
mdbx_mapresize:7772 resize datafile/mapping: present 443860238336 -> 443985469440, limit 2199023255552 -> 2199023255552

[erthink]

1. У меня получилось воспроизвести вторичную проблему с аудитом (MDBX_PROBLEM при коммите) в тестах на больших транзакциях. Это очень похоже на регресс наведенный какими-то последними правками. Сейчас разбираюсь и (предположительно) сегодня поправлю.
2. Чтобы получить лог для устранения исходной проблемы (MDBX_KEYEXIST при коммите) НУЖНО приложить патч и включить логирование без аудита mdbx_setup_debug(MDBX_LOG_VERBOSE, MDBX_DBG_ASSERT, your_logger). Тогда вы увидите небольшие логи, преимущественно с префиксом mdbx_update_gc: - именно они и нужны.
   Всё что получилось выше, к сожалению, совсем не содержит требуемой информации.

[AskAlexSharov]

mdbx_update_gc.log

[erthink]

Похоже обе проблемы являются регрессом после #121.

Грубо говоря, из-за регресса в каких-то ситуациях из GC удаляется не то что нужно.
Соответственно, как только это происходит, случается либо MDBX_KEYEXIST при обновлении GC, либо потеря записей GC (т.е. выпадение страниц из учета) и MDBX_PROBLEM при включенном аудите.

[erthink]

@AskAlexSharov, предположительно проблема связана с трекингом курсоров - когда для одного DBI открыто несколько курсоров, и удаления/вставки, выполняемые через один курсор, должны отображаться на состояние остальных. Под состоянием курсора тут понимается не только "флажки", но и стек страниц от корня дерева с позициями в них.

Похоже что это еще одна унаследованная из LMDB ошибка, которая не проявлялась до исправления #121. Для надежного исправления мне потребуется доработать тесты и тщательно всё перепроверить, на что потребуется до 2 недель.

[AskAlexSharov]

Great. If it’s clearly inherited problem, share to Howard your reaults please.

[AskAlexSharov]

Faced new (probably with same root-cause problem) on master 21d2af9 :
code like

cursor.Last()
for {
   // ... get key, value from sorted list
   cursor.Put(key, value, AppendDup)
}

returns error MDBX_EKEYMISMATCH: The given key value is mismatched to the current cursor position
I wonder if cursor must be in "some position" for AppendDup.

[erthink]

I wonder if cursor must be in "some position" for AppendDup.

This is just a one/common message for error returned in similar cases, i.e. when the key/data don't match the cursor position (virtual or implied):

• MDBX_APPENDDUP = data value must be great than any present duplicate/multivalue for the specified key.
• MDBX_APPEND = key value must be great (or equal for DUPSORT-database) than any key of DBI/sub-database, but no restriction for data value (include DUPSORT-databases).
• MDBX_APPEND | MDBX_APPENDDUP = both of above.
• MDBX_CURRENT = key must match the current cursor position.

Are you sure that in your case the values for each key are added in ascending order?

[AskAlexSharov]

"Are you sure that in your case the values for each key are added in ascending order?" - you are right. I just get used to another error of LMDB in this case. Nevermind then.

[erthink]

У меня получилось воспроизвести вторичную проблему с аудитом (MDBX_PROBLEM при коммите) в тестах на больших транзакциях. Это очень похоже на регресс наведенный какими-то последними правками. Сейчас разбираюсь и (предположительно) сегодня поправлю.

Пока хороших новостей нет:

• Проблема НЕ проявляется с пробными/черновыми исправлениями, однако повторно воспроизвести её и БЕЗ исправлений также НЕ получилось.
• Т.е. в тестах проблема воспроизводится при каком-то достаточно редком стечении обстоятельств, которые пока не удалось выявить и/или формализовать.

[erthink]

@AskAlexSharov, если у вас есть более-менее стабильный сценарий воспроизведения, то желательно чтобы вы попробовали ветку fix-31.

[AskAlexSharov]

Нет, проблема c audit не воспроизводится на master/fix-131/debug-gc-update

[erthink]

Текущее состояние дел:

1. После однократного воспроизведения проблему повторить не удалось. При этом тест был повторен на различных машинах суммарно порядка 10000 раз, с фиксированным random-seed как при однократном воспроизведении.
2. Доработку тестов и связанные с этим исправления я почти завершил и сегодня-завтра пролью эти правки (после завершения тестов и рефакторинга).
3. Доработанные тесты выявили несколько багов/недочетов, но все они вне традиционных сценариев использования и не объясняют замеченную проблему.

[AskAlexSharov]

1. Какую именно проблему? MDBX_KEYEXIST или MDBX_PROBLEM? (вторая у меня не воспроизводится, первая у меня воспроизводится при drop 30Gb DupSort DBI). В любом случае готов запускать наши тесты на новой ветке.

[erthink]

1. Какую именно проблему? MDBX_KEYEXIST или MDBX_PROBLEM? (вторая у меня не воспроизводится, первая у меня воспроизводится при drop 30Gb DupSort DBI). В любом случае готов запускать наши тесты на новой ветке.

MDBX_PROBLEM было в ваших логах, когда вместе с отладкой вы включили аудит.
После чего я предположил что это два проявления одной проблемы.

Сейчас я пролью правки в ветку devel и вам стоит её попробовать на ваших кейсах, ибо мне удалось воспроизвести проблему только однократно.

[AskAlexSharov]

В новом devel 56a52b0 при drop 30Gb DupSort DBI:
mdbx_txn_commit_ex: MDBX_KEYEXIST: Key/data pair already exists

env: NoReadahead | LifoReclaim | Coalesce | Durable

[erthink]

Видимо мне всё-таки придется скачать вашу тестовую базу и поковыряться локально.
Иначе не понятно как воспроизводить.

[AskAlexSharov]

Нет, я ошибся.

То место которое раньше показывало MDBX_KEYEXIST: Key/data pair already exists сейчас показывает MDBX_TXN_FULL: Transaction has too many dirty pages, i.e transaction is too big.

mdbx_stat -s - показывает, что тот DBI который я дропаю пуст. Т.е. MDBX_TXN_FULL я получаю на транзакции которая делает 2 действия - дропает dbi, создает dbi, commit.

Но у этой базы большой фрилист:
mdb_stat_ff.log

Сейчас попробую убрать LifoReclaim флаг.

[erthink]

Хорошо, погоняйте/потестируйте ещё.
Сейчас важно "есть слона частями" - сначала разобраться с MDBX_KEYEXIST (основной функционал), а уже после с MDBX_TXN_FULL (улучшения).

[erthink]

@AskAlexSharov, пожалуйста попробуйте (несколько раз, по-разному и т.п.) воспроизвести проблему на ветке devel.
Если не получиться, то будем считать что баг устранен и я займусь MDBX_TXN_FULL (в том числе попробую малыми усилиями задействовать интервалы в списках страниц).

[AskAlexSharov]

Да, я запустил жирный тест. Но, он занимает несколько дней, думаю остались сутки до конца. Думаю можно считать что баг устранен, а о результатах тестов я напишу через день-два.

[AskAlexSharov]

Закончил тестирование. Специальных ошибок не возникает - но результат не сходится (в той части приложения где у нас кастомный dcmp). Пока не нашел причины - занимаюсь.

[erthink]

Дайте больше информации о расхождениях, я подумаю что может быть.

Кроме этого, после расширения тестов курсоров и соответствующих доработок поведение курсоров стало более унифицированным, но поменялось (см ниже). При этом я стремился не менять поведение и сделать его максимально идентичным LMDB (т.е. так как задумывал Говард Чу). Тем не менее, отличия от LMDB скорее всего есть, но из-за ошибок/недочетов в LMDB (вернуть эти правки проблематично, нужно начинать с тестов).

Исправления поведения курсоров:

• использование курсора после неудачного поиска, вместо возврата ошибки, могло приводить к падению или получению левых данных.
• переходы NEXT/PREV могли оставлять курсор в неверном состоянии (похоже на предыдущий случай).

[erthink]

Есть ли какая-нибудь новая информация?

[AskAlexSharov]

К сожалению, пока проблема возникла 2 раза, но нормально воспроизвести и конкретизировать не удалось.

[erthink]

Так в двух словах - какие расхождения вы наблюдаете?
Т.е. что не так?

[AskAlexSharov]

Есть часть приложения: 2 курсора - один dupsort без кастомного dcmp, другой dupaort с кастомным dcmp. Курсоры бегут только вперед - иногда next, иногда setRange, иногда setBothRange. Все полученные данные пропускаются через хеш-функцию - вот этот хеш не сошелся.

Ну, т.е. по пути много чего могло пойти не так.

[erthink]

На всякий:

• setBothRange требует чтобы ключ был и при его наличии переходит к equal or great значению среди дубликатов.
• Позиционирование курсоров тестируется как тестами в libmdbx, так и в libfpta. Пока не представляю где тут могут быть проблемы.
• При удалении или изменении записей в позиции курсора (через другой курсор) могут быть неожиданные эффекты, особенно в случае DUPSORT. Если у вас есть такие сценарии их лучше избежать (напишите при необходимости, я поясню).

[AskAlexSharov]

Может быть и нет проблемы, раз не воспроизводится.

“ При удалении или изменении записей в позиции курсора (через другой курсор) могут быть неожиданные эффекты, особенно в случае DUPSORT. Если у вас есть такие сценарии их лучше избежать (напишите при необходимости, я поясню).” - мы перешли на пары курсоров (один читает, второй удаляет) везде потому-что это тот самый баг lmdb с которого у нас тут все началось :-) я поменяю приложение чтобы оно использовало только 1 курсор на 1 DBI.