Снова лечим дедлоки (deadlocks)

[Efendy]

Данная тема создана по мотивам данной темы

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

Практически всегда в этом виновны так называемые дедлоки (deadlocks) в базе данных. Если коротко, то в базе данных есть механизм локов, это не что-то плохое, он предназначен для сохранения консистентности базы данных. Но бывают ситуации, когда локи "превращаются" в мертвые и записи в БД долго остаются заблокированными, что приводит к тупнякам.

Почему это происходит? С одной стороны, в этом есть вина движка mysql, с другой стороны нужно менять sql запросы так, чтобы они не приводили к дедлокам. Однако, не всегда это возможно. Более того, не всегда можно понять почему, черт возьми, этот запрос привел к дедлокам.

Одним из проблемных sql был запрос на создание/продление авторизации. Есть таблица auth_now, которая хранит текущие авторизации. Когда приходит запрос от Радиуса "такой-то перец авторизован", то процедура NoDeny пытается создать запись в таблице auth_now, а если она там уже есть, то пытается заапдейтить (обновить актуальные данные).

В mysql есть механизм для выполнения этих действий как единого целого (а нам для корректности и безглючности именно это и нужно) - INSERT ... ON DUPLICATE KEY UPDATE - либо вставляем, либо обновляем если запись есть.

Вот этот запрос приводил к дедлокам. Если честно, я не вижу логики почему. Вернее, я вижу косвенную причину, хотя и не понимаю, почему она возникает. Короче. Судя по логам, проблема возникает на конфликте поля Id. Вероятно, когда insert откатывается, идет попытка отката поля id, а оно заблокировано.

Что такое поле id? Оно есть практически во всех таблицах и нужно для того, чтобы как-то идентифицировать запись, грубо говоря номер строки. Это поле автинкрементное и при вставке любой записи оно становится +1. В общем, поле нужное. Практически всегда.

Я обратил внимание, что NoDeny нет никакой необходимости нумеровать записи в таблице авторизации. Да, поле теоретически полезное, но оно никак не используется. А проблема именно в нем. Поэтому я пришел к чисто Сталлинскому решению: нет поля, нет проблемы. И предложил удалить это поле автору топика в начале данного.

И судя по его данным, все получилось. Повторюсь, что нужно сделать:

Код:

alter table auth_now drop id;

[Warlock]

у меня почему-то локи появляются в ip_pool

Код:

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 35235 n bits 440 index `PRIMARY` of table `nodeny`.`ip_pool` trx id 10455A2C0D lock_mode X locks rec but not gap
Record lock, heap no 120 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 00000eb8; asc     ;;
 1: len 6; hex 0010455a2c1d; asc   EZ, ;;
 2: len 7; hex 5f0004401a215e; asc _  @ !^;;
 3: len 4; hex c1a8be73; asc    s;;
 4: len 1; hex 02; asc  ;;
 5: len 1; hex 00; asc  ;;
 6: len 4; hex 5f4467f4; asc _Dg ;;
 7: len 8; hex 0000000000001611; asc         ;;
 8: len 0; hex ; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 35235 n bits 440 index `PRIMARY` of table `nodeny`.`ip_pool` trx id 10455A2C0D lock_mode X locks rec but not gap waiting
Record lock, heap no 101 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 00000ea5; asc     ;;
 1: len 6; hex 0010455a2c16; asc   EZ, ;;
 2: len 7; hex 5a000195681048; asc Z   h H;;
 3: len 4; hex 2d952bab; asc - + ;;
 4: len 1; hex 02; asc  ;;
 5: len 1; hex 00; asc  ;;
 6: len 4; hex 5f4467f4; asc _Dg ;;
 7: len 8; hex 0000000000001077; asc        w;;
 8: len 0; hex ; asc ;;

[Efendy]

Ты читал мое предыдущее сообщение? Локи и дедлоки - это разные вещи. Локи - нормально. Дедлоки - нет. В твоем сообщении я не увидел дедлоки, или ты не все процитировал. Даже в твоем имени есть лок, но ты же нормально с этим живешь?

[sedo26]

Доброе утро, начали появляться непонятные ошибки в логе mysql.
Несколько минут всё повисит и отпускает, бывает надо перегружать сервер.

Код:

=====================================
2020-09-16 08:03:27 a85b88100 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 16 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 3 srv_active, 0 srv_shutdown, 2 srv_idle
srv_master_thread log flush and writes: 4
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 234
--Thread 45217058304 has waited at lock0lock.cc line 6839 for 747.00 seconds the semaphore:
Mutex at 0xa86a00068 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 45217599488 has waited at lock0lock.cc line 6312 for 747.00 seconds the semaphore:
Mutex at 0xa86a00068 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 45217068544 has waited at lock0lock.cc line 4418 for 747.00 seconds the semaphore:
Mutex at 0xa86a00068 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 34416470016 has waited at lock0lock.cc line 3422 for 746.00 seconds the semaphore:
Mutex at 0xa86a00068 created file lock0lock.cc line 611, lock var 1
waiters flag 1
--Thread 45193431552 has waited at btr0cur.cc line 256 for 745.00 seconds the semaphore:
S-lock on RW-latch at 0xa7d556b40 created in file buf0buf.cc line 1069
a writer (thread id 34416470016) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 256
Last time write locked in file /wrkdirs/usr/ports/databases/mysql56-server/work/mysql-5.6.40/storage/innobase/btr/btr0cur.cc line 256
--Thread 45193131776 has waited at lock0wait.cc line 457 for 696.00 seconds the semaphore:
Mutex at 0xa86a00068 created file lock0lock.cc line 611, lock var 1
waiters flag 1

на НАСе в это время в dhcp.events.log

Код:

 UPDATE mac_uid SET ip=0 WHERE ip=INET_ATON('192.168.22.195') AND mac<>'c07e404844ee'
16.09.2020 07:26:17 Connecting to DBI:mysql:database=nodeny;host=xxx.xxx.xxx.xxx;port=3306;mysql_connect_timeout=5 : 0.000754 sec
16.09.2020 07:27:08 Lock wait timeout exceeded; try restarting transaction

{
  'sql' => 'UPDATE mac_uid SET mac=NULL, ip=0 WHERE mac=? AND (device_mac<>? OR device_port<>?)',
  'param' => [
    'c07e404844ee',
    '',
    0
  ]
};

Может у кого было подобное.

[NTE]

Я обратил внимание, что NoDeny нет никакой необходимости нумеровать записи в таблице авторизации. Да, поле теоретически полезное, но оно никак не используется. А проблема именно в нем. Поэтому я пришел к чисто Сталлинскому решению: нет поля, нет проблемы. И предложил удалить это поле автору топика в начале данного.

Добрый день.
Станислав, как можно увидеть есть такие мертвые записи или нет?

[veca16]

Добрый вечер! Столкнулся с Дедлоком у одного из обслуживаемых серверов.

Код:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-11-02 20:37:00 923e24000
*** (1) TRANSACTION:
TRANSACTION 11319377117, ACTIVE 0 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 42 row lock(s)
MySQL thread id 27269, OS thread handle 0x91f1de800, query id 301542117 localhost nodeny updating
UPDATE ip_pool SET uid=0 WHERE type='dynamic' AND uid>0 AND `release`<UNIX_TIMESTAMP()
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1 page no 9 n bits 440 index `PRIMARY` of table `nodeny`.`ip_pool` trx id 11319377117 lock_mode X waiting
Record lock, heap no 43 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 00000327; asc    ';;
 1: len 6; hex 0000e08bedb8; asc       ;;
 2: len 7; hex 19000002ac0eb4; asc        ;;
 3: len 4; hex 0a0a002b; asc    +;;
 4: len 1; hex 01; asc  ;;
 5: len 1; hex 00; asc  ;;
 6: len 4; hex 566573df; asc Ves ;;
 7: len 8; hex 0000000000000000; asc         ;;
 8: len 0; hex ; asc ;;

*** (2) TRANSACTION:
TRANSACTION 11319377116, ACTIVE 0 sec starting index read
mysql tables in use 2, locked 1
10 lock struct(s), heap size 2936, 1934 row lock(s)
MySQL thread id 27585, OS thread handle 0x923e24000, query id 301542120 localhost nodeny init
UPDATE ip_pool SET uid = user_id, `release` = UNIX_TIMESTAMP() + 300 
        WHERE (uid = 0 OR uid = user_id)
            AND type = 'dynamic'
            AND realip = IF(real_ip>0,1,0)
        ORDER BY uid DESC, ip ASC LIMIT 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1 page no 9 n bits 440 index `PRIMARY` of table `nodeny`.`ip_pool` trx id 11319377116 lock_mode X locks rec but not gap
Record lock, heap no 43 PHYSICAL RECORD: n_fields 9; compact format; info bits 0
 0: len 4; hex 00000327; asc    ';;
 1: len 6; hex 0000e08bedb8; asc       ;;
 2: len 7; hex 19000002ac0eb4; asc        ;;
 3: len 4; hex 0a0a002b; asc    +;;
 4: len 1; hex 01; asc  ;;
 5: len 1; hex 00; asc  ;;
 6: len 4; hex 566573df; asc Ves ;;
 7: len 8; hex 0000000000000000; asc         ;;
 8: len 0; hex ; asc ;;

Что с ним делать пока незнаю, подскажите пожалуйста что возможно сделать.
Так как система на этом сервере freebsd 10.2 а mysql 5.6 и Nodeny Plus еще одна из первых версий, тоесть довольно старая то у меня вариант только обновить все до более нового и перенастроить по-новому.
Подскажите ребята может ли помочь это? Заранее спасибо.

[veca16]

Забыл написать что лок проявляется примерно раз в час, но при этом слелетает большинство авторизаций и по большей части сети происходит дисконнект.

[Efendy]

Похоже у тебя устаревшая версия NoDeny. В ней периодически выполняется запрос освобождения динамических ip

Код:

UPDATE ip_pool SET uid=0 WHERE type='dynamic' AND uid>0 AND `release`<UNIX_TIMESTAMP()

и из-за того, что в выборку может попасть много записей, может сильно залочится. Я это пофиксил (влом смотреть когда), но ты можешь посмотреть файл /usr/local/nodeny/kernel/auth.pm, сейчас там:

Код:

    # Освобождение динамических ip
    my $db = Db->sql("SELECT id FROM ip_pool WHERE type='dynamic' AND uid>0 AND `release`<UNIX_TIMESTAMP()");
    while( my %p = $db->line )
    {
        my $rows = Db->do("UPDATE ip_pool SET uid=0 WHERE type='dynamic' AND uid>0 AND `release`<UNIX_TIMESTAMP() AND id=?", $p{id});
        Db->ok or last;
    }

т.е. сначала получаем список ip для особождения, а потом по одному их освобождаем