Kernel Message: INFO: task program:pid blocked for more than 120 seconds. [solved]

От известно време на една production машина взе да излизат подобни errors като този: 

[71521.708522] INFO: task apache2:12319 blocked for more than 120 seconds.
[71521.708567] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[71521.708612] apache2       D c10c5be2     0 12319   1564 0x00000000
[71521.708616]  f686f700 00200082 d2227c38 c10c5be2 d0684354 00000008 00000000 f6997019
[71521.708622]  010f9a20 c142ee80 f686f8bc c142a354 c10be7f4 f686f700 f686f8bc c142ee80
[71521.708628]  d726feac 00000000 00000000 00000000 f5636114 f686f700 f5636118 00000002
[71521.708633] Call Trace:
[71521.708640]  [<c10c5be2>] ? __d_lookup+0xa0/0xd4
[71521.708645]  [<c10be7f4>] ? do_lookup+0x49/0x112
[71521.708650]  [<c12738ee>] ? __mutex_lock_common+0xe7/0x138
[71521.708653]  [<c127394e>] ? __mutex_lock_slowpath+0xf/0x11
[71521.708656]  [<c12737a1>] ? mutex_lock+0x10/0x1d
[71521.708659]  [<c12737a1>] ? mutex_lock+0x10/0x1d
[71521.708663]  [<c10c1080>] ? do_filp_open+0x1da/0x7e3
[71521.708667]  [<c10aa3fc>] ? free_pages_and_swap_cache+0x43/0x50
[71521.708672]  [<c10c8515>] ? alloc_fd+0x4f/0xb1
[71521.708675]  [<c10b6804>] ? do_sys_open+0x49/0xdd
[71521.708678]  [<c10b68dc>] ? sys_open+0x1e/0x23
[71521.708682]  [<c10080db>] ? sysenter_do_call+0x12/0x28
[71521.708687]  [<c127007b>] ? native_cpu_up+0x1ea/0x594
[71521.708692] INFO: task php:14290 blocked for more than 120 seconds.
[71521.708735] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[71521.708780] php           D c10c5be2     0 14290  14289 0x00000000
[71521.708783]  f5a4d500 00000086 d2227c38 c10c5be2 d0604354 00000008 00000000 f6a43019
[71521.708789]  010fada7 c142ee80 f5a4d6bc c142a354 c10be7f4 f5a4d500 f5a4d6bc c142ee80
[71521.708795]  da11feac 00000000 00000000 00000000 f5636114 f5a4d500 f5636118 00000002
[71521.708800] Call Trace:
[71521.708803]  [<c10c5be2>] ? __d_lookup+0xa0/0xd4
[71521.708806]  [<c10be7f4>] ? do_lookup+0x49/0x112
[71521.708809]  [<c12738ee>] ? __mutex_lock_common+0xe7/0x138
[71521.708813]  [<c127394e>] ? __mutex_lock_slowpath+0xf/0x11
[71521.708816]  [<c12737a1>] ? mutex_lock+0x10/0x1d
[71521.708818]  [<c12737a1>] ? mutex_lock+0x10/0x1d
[71521.708822]  [<c10c1080>] ? do_filp_open+0x1da/0x7e3
[71521.708826]  [<c10c8515>] ? alloc_fd+0x4f/0xb1
[71521.708829]  [<c10b6804>] ? do_sys_open+0x49/0xdd
[71521.708832]  [<c1275ed6>] ? do_page_fault+0x2e7/0x2fd
[71521.708835]  [<c10b68dc>] ? sys_open+0x1e/0x23
[71521.708838]  [<c10080db>] ? sysenter_do_call+0x12/0x28

Машината буквално "увисва" за няколко минути. Оказа се че в crontab-a е сложен нов скрипт който изтрива някакви cache файлове.

Какво се оказа. Линукс ядрото кешира всичките дискови операции в паметта като когато се достигне определен процент от заетата RAM, дисковите операции се форсират да се запишат на хард диска. По подразниране в линукс ядрото при 40% от заетата рам се форсира записването им на хард диска, като записа става синхронно тоест всички останали процеси са блокирани за достъп към твърдия диск. От тук идва и проблема, машината е с 16 гигабайта RAM и 40% от 16gb не са никак малко. При достигането на 40% от паметта, форсираното записване продължава повече от 120 секунди (което е някакъв лимит за колко време може да отнеме тази операция) понеже диска не е толкова бърз за да запише всичко се изплюва тази грешка и като резултат машината е недостъпна известно време.

Процентното съотношение на може да се контролира през /etc/sysctl.conf:

vm.dirty_ratio = 7

или с команда:

sysctl vm.dirty_ratio=7

Това указва на ядрото кешираните IO операции да са не повече от 7% от общата RAM.