FreenetIS

Chyba už se objevila vícekrát, je nutné zjistit její příčinu. (možná nějaké souběžné čtení? chyba v DB serveru)

Opraveno v r1645. Možná příčina - povolené subnety (chyba se objevovala v scheduleru, u mazaní a přidávání zařízení a jediné co tyto akce spojuje jsou právě pocvolené subnety)

Tak chyba ještě není uzavřena - je potřeba otestovat v ostrém provozu

Nepomohlo:

2012-08-17 12:55:04 -- error: Chyba transakce: Chyba v SQL dotazu - Deadlock found when trying to get lock; try restarting transaction v souboru /var/www/freenetis/system/libraries/drivers/Database/Mysql.php na řádku 374 - 
Zásobník #0 /var/www/freenetis/system/libraries/drivers/Database/Mysql.php(99): Mysql_Result->__construct(false, Resource id #30, true, 'INSERT INTO `ip...')
#1 /var/www/freenetis/system/libraries/Database.php(181): Database_Mysql_Driver->query('INSERT INTO `ip...')
#2 /var/www/freenetis/system/libraries/Database.php(884): Database->query('INSERT INTO `ip...')
#3 /var/www/freenetis/system/libraries/ORM.php(787): Database->insert('ip_addresses', Array)
#4 /var/www/freenetis/system/libraries/ORM.php(1567): ORM_Core->save()
#5 /var/www/freenetis/application/controllers/devices.php(1162): ORM_Core->save_throwable()
#6 /var/www/freenetis/system/core/Kohana.php(330): Devices_Controller->add('1344')
#7 [internal function]: Kohana::instance()
#8 /var/www/freenetis/system/core/Event.php(217): call_user_func(Array)
#9 /var/www/freenetis/system/core/Bootstrap.php(55): Event::run('system.execute')
#10 /var/www/freenetis/index.php(86): require('/var/www/freene...')
#11 {main}   URL: cs/devices/add/1344?path_qsurl=devices%2Fshow_by_user%2F1344

Žádná chyba v logu :-)

Ne :-(

2012-08-20 10:31:17 -- error: Chyba transakce: Chyba v SQL dotazu - Deadlock found when trying to get lock; try restarting transaction v souboru /var/www/freenetis/system/libraries/drivers/Database/Mysql.php na řádku 374 - 
Zásobník #0 /var/www/freenetis/system/libraries/drivers/Database/Mysql.php(99): Mysql_Result->__construct(false, Resource id #30, true, 'INSERT INTO `ip...')
#1 /var/www/freenetis/system/libraries/Database.php(181): Database_Mysql_Driver->query('INSERT INTO `ip...')
#2 /var/www/freenetis/system/libraries/Database.php(884): Database->query('INSERT INTO `ip...')
#3 /var/www/freenetis/system/libraries/ORM.php(787): Database->insert('ip_addresses', Array)
#4 /var/www/freenetis/system/libraries/ORM.php(1567): ORM_Core->save()
#5 /var/www/freenetis/application/controllers/devices.php(1162): ORM_Core->save_throwable()
#6 /var/www/freenetis/system/core/Kohana.php(330): Devices_Controller->add('658')
#7 [internal function]: Kohana::instance()
#8 /var/www/freenetis/system/core/Event.php(217): call_user_func(Array)
#9 /var/www/freenetis/system/core/Bootstrap.php(55): Event::run('system.execute')
#10 /var/www/freenetis/index.php(86): require('/var/www/freene...')
#11 {main}   URL: cs/devices/add/658?path_qsurl=devices%2Fshow_by_user%2F658

Vypdá že OK, snad :-)

Po delší době jsem prohlédl logy a problém stále přetrvává.

Opět jsem se zkusil problému podívat na kobylku a zjistil jsem, že jsme docela v nezáviděhodné situaci. Strácím víru v InnoDB engine MySQL. Dokumentace radí, že nejlepší způsob jak pracovat s deadlocky, je postižený kód spuzstit znovu, což mi připadá v našem případě jako sci-fi.

Největší problém je u tabulky ip_addresses, která je neskutečně vytěžována:

1. webové rozhraní pro komunikaci s okolím (přesměrování, monitoring, ulog, ...)
2. CRON (povolené podsítě)
3. zařízení (přidávání, mazání)

A když se to všechno udělá zaráz tak to bouchne. Při každém výbuchu je nutné udělat výpis stavu Inna a hodit ho sem. Pak budem moct anylyzovat, co by se dalo udělat, abychom se zbavili a poučili z této obludnosti.

Přikládám poslední deadlock (příkaz SHOW ENGINE INNODB STATUS):

LATEST DETECTED DEADLOCK
------------------------
120927 12:10:13
*** (1) TRANSACTION:
TRANSACTION 0 543342137, ACTIVE 1 sec, process no 1940, OS thread id 140077990967040 starting index read
mysql tables in use 3, locked 3
LOCK WAIT 69 lock struct(s), heap size 14320, 28744 row lock(s)
MySQL thread id 22205728, query id 609321449 localhost freenetis Sending data
UPDATE monitor_hosts mh,
            (
                SELECT i.device_id
                FROM ip_addresses ip
                JOIN ifaces i ON ip.iface_id = i.id
                WHERE ip_address = '10.143.130.163'
            ) ip
            SET
                state = 1,
                state_changed = IF(state <> 1, 1, 0),
                state_changed_date = IF(state <> 1, NOW(), state_changed_date),
                last_attempt_date = NOW(),
                latency_current = '5.84\n',
                latency_min = IF('5.84\n' IS NOT NULL AND (latency_min IS NULL OR latency_min > '5.84\n'), '5.84\n', latency_min),
                latency_max = IF('5.84\n' IS NOT NULL AND (latency_max IS NULL OR latency_max < '5.84\n'), '5.84\n', latency_max),
                latency_avg = (IFNULL(latency_avg,0) * (polls_total - polls_failed) + '5.84\n')/(polls_total + 1 - polls_failed - 0),
                polls_total = polls_total + 1,
                polls_failed = polls_failed + 0,
                availability = ROUND((polls_total + 1 - polls_failed - 0)/(polls_total + 1)*100, 2)
            WHERE ip.device_id = mh.device_id
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 19073 n bits 392 index `PRIMARY` of table `freenetis`.`ip_addresses` trx id 0 543342137 lock mode S locks rec but not gap waiting
Record lock, heap no 53 PHYSICAL RECORD: n_fields 11; compact format; info bits 32
 0: len 4; hex 80004058; asc   @X;; 1: len 6; hex 00002062be41; asc    b A;; 2: len 7; hex 000000003e0b31; asc     > 1;; 3: len 4; hex 80003016; asc   0 ;; 4: len 4; hex 8000023f; asc    ?;; 5: SQL NULL; 6: len 12; hex 31302e3134332e3230372e35; asc 10.143.207.5;; 7: SQL NULL; 8: len 1; hex 80; asc  ;; 9: len 1; hex 80; asc  ;; 10: len 1; hex 80; asc  ;;

*** (2) TRANSACTION:
TRANSACTION 0 543342145, ACTIVE 0 sec, process no 1940, OS thread id 140077993977600 updating or deleting, thread declared inside InnoDB 1
mysql tables in use 1, locked 1
25 lock struct(s), heap size 6752, 14 row lock(s), undo log entries 4
MySQL thread id 22206631, query id 609321519 localhost freenetis updating
DELETE FROM `devices` WHERE `id` = 11634
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 19073 n bits 392 index `PRIMARY` of table `freenetis`.`ip_addresses` trx id 0 543342145 lock_mode X locks rec but not gap
Record lock, heap no 53 PHYSICAL RECORD: n_fields 11; compact format; info bits 32
 0: len 4; hex 80004058; asc   @X;; 1: len 6; hex 00002062be41; asc    b A;; 2: len 7; hex 000000003e0b31; asc     > 1;; 3: len 4; hex 80003016; asc   0 ;; 4: len 4; hex 8000023f; asc    ?;; 5: SQL NULL; 6: len 12; hex 31302e3134332e3230372e35; asc 10.143.207.5;; 7: SQL NULL; 8: len 1; hex 80; asc  ;; 9: len 1; hex 80; asc  ;; 10: len 1; hex 80; asc  ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 11677 n bits 1184 index `iface_id` of table `freenetis`.`ip_addresses` trx id 0 543342145 lock_mode X locks rec but not gap waiting
Record lock, heap no 618 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80003016; asc   0 ;; 1: len 4; hex 80004058; asc   @X;;

*** WE ROLL BACK TRANSACTION (2)

Použito v changesetu r1762.