歡迎來到Linux教程網
Linux教程網
Linux教程網
Linux教程網
Linux教程網 >> Linux綜合 >> 學習Linux >> Linux 日志報錯 xxx blocked for more than 120 seconds,blockedseconds

Linux 日志報錯 xxx blocked for more than 120 seconds,blockedseconds

日期:2017/3/6 9:22:32   编辑:學習Linux

Linux 日志報錯 xxx blocked for more than 120 seconds,blockedseconds


Linux 日志報錯 xxx blocked for more than 120 seconds,blockedseconds


監控作業發現一台服務器(Red Hat Enterprise Linux Server release 5.7)從凌晨1:32開始,有一小段時間無法響應,數據庫也連接不上,後面又正常了。早上檢查了監聽日志,並沒有發現錯誤信息。但是檢查告警日志,發現有下面錯誤信息:

Thread 1 advanced to log sequence 19749 (LGWR switch)
  Current log# 2 seq# 19749 mem# 0: /u01/oradata/epps/redo02.log
  Current log# 2 seq# 19749 mem# 1: /u03/oradata/epps/redo021.log
Wed Aug 17 01:37:08 2016
kkjcre1p: unable to spawn jobq slave process 
Wed Aug 17 01:37:08 2016
Errors in file /u01/app/oracle/admin/epps/bdump/epps_cjq0_4094.trc:
 
Wed Aug 17 01:56:44 2016
kkjcre1p: unable to spawn jobq slave process 
Wed Aug 17 01:56:44 2016
Errors in file /u01/app/oracle/admin/epps/bdump/epps_cjq0_4094.trc:

more /u01/app/oracle/admin/epps/bdump/epps_cjq0_4094.trc
u01/app/oracle/admin/epps/bdump/epps_cjq0_4094.trc
racle Database 10g Release 10.2.0.4.0 - 64bit Production
RACLE_HOME = /u01/app/oracle/product/10.2.0/db_1
ystem name:    Linux
ode name:      ceglnx01
elease:        2.6.32-200.13.1.el5uek
ersion:        #1 SMP Wed Jul 27 21:02:33 EDT 2011
achine:        x86_64
nstance name: epps
edo thread mounted by this instance: 1
racle process number: 17
nix process pid: 4094, image: oracle@ceglnx01 (CJQ0)
 
** 2016-08-13 01:52:16.178
** SERVICE NAME:(SYS$BACKGROUND) 2016-08-13 01:52:16.155
** SESSION ID:(177.9) 2016-08-13 01:52:16.155
aited for process J000 to be spawned for 60 seconds
** 2016-08-13 01:52:26.187
aited for process J000 to be spawned for 70 seconds
** 2016-08-13 01:52:36.197
aited for process J000 to be spawned for 80 seconds
** 2016-08-13 01:52:46.207
aited for process J000 to be spawned for 90 seconds
** 2016-08-13 01:52:56.217
aited for process J000 to be spawned for 100 seconds
** 2016-08-13 01:53:06.227
aited for process J000 to be spawned for 110 seconds
** 2016-08-13 01:57:15.512
** 2016-08-14 01:30:52.159
aited for process J000 to be spawned for 60 seconds
** 2016-08-14 01:31:02.186
aited for process J000 to be spawned for 70 seconds
** 2016-08-14 01:31:12.196
aited for process J000 to be spawned for 80 seconds
** 2016-08-14 01:31:22.206
aited for process J000 to be spawned for 90 seconds
** 2016-08-14 01:31:32.217
aited for process J000 to be spawned for 100 seconds
** 2016-08-14 01:31:42.227
aited for process J000 to be spawned for 110 seconds
** 2016-08-14 01:35:36.155
** 2016-08-14 01:44:46.866
aited for process J000 to be spawned for 60 seconds
** 2016-08-14 01:44:56.876
aited for process J000 to be spawned for 70 seconds
** 2016-08-14 01:45:06.886
aited for process J000 to be spawned for 80 seconds
** 2016-08-14 01:45:16.896
aited for process J000 to be spawned for 90 seconds
** 2016-08-14 01:45:26.906
aited for process J000 to be spawned for 100 seconds
** 2016-08-14 01:45:36.916
aited for process J000 to be spawned for 110 seconds
** 2016-08-14 01:55:49.977
** 2016-08-14 01:58:22.156
aited for process J000 to be spawned for 60 seconds
** 2016-08-14 01:58:32.166
aited for process J000 to be spawned for 70 seconds
** 2016-08-14 01:58:42.176
aited for process J000 to be spawned for 80 seconds
** 2016-08-14 01:58:52.187
aited for process J000 to be spawned for 90 seconds
** 2016-08-14 01:59:02.196
aited for process J000 to be spawned for 100 seconds
** 2016-08-14 01:59:12.206
aited for process J000 to be spawned for 110 seconds
** 2016-08-14 02:17:55.867
** 2016-08-16 01:30:52.151
aited for process J000 to be spawned for 60 seconds
** 2016-08-16 01:31:02.180
aited for process J000 to be spawned for 70 seconds
** 2016-08-16 01:31:12.191
aited for process J000 to be spawned for 80 seconds
** 2016-08-16 01:31:22.202
aited for process J000 to be spawned for 90 seconds
** 2016-08-16 01:31:32.213
aited for process J000 to be spawned for 100 seconds
** 2016-08-16 01:31:42.223
aited for process J000 to be spawned for 110 seconds
** 2016-08-16 01:35:09.610
** 2016-08-16 01:51:50.369
aited for process J000 to be spawned for 60 seconds
** 2016-08-16 01:52:00.379
aited for process J000 to be spawned for 70 seconds
** 2016-08-16 01:52:10.389
aited for process J000 to be spawned for 80 seconds
** 2016-08-16 01:52:20.399
aited for process J000 to be spawned for 90 seconds
** 2016-08-16 01:52:30.409
aited for process J000 to be spawned for 100 seconds
** 2016-08-16 01:52:40.419
aited for process J000 to be spawned for 110 seconds
** 2016-08-16 01:56:11.022
** 2016-08-17 01:22:21.154
aited for process J000 to be spawned for 60 seconds
** 2016-08-17 01:22:31.190
aited for process J000 to be spawned for 70 seconds
** 2016-08-17 01:22:41.199
aited for process J000 to be spawned for 80 seconds
** 2016-08-17 01:22:51.209
aited for process J000 to be spawned for 90 seconds
** 2016-08-17 01:23:01.219
aited for process J000 to be spawned for 100 seconds
** 2016-08-17 01:23:11.229
aited for process J000 to be spawned for 110 seconds
** 2016-08-17 01:37:08.240
** 2016-08-17 01:38:08.401
aited for process J000 to be spawned for 60 seconds
** 2016-08-17 01:38:18.412
aited for process J000 to be spawned for 70 seconds
** 2016-08-17 01:38:28.421
aited for process J000 to be spawned for 80 seconds
** 2016-08-17 01:38:38.431
aited for process J000 to be spawned for 90 seconds
** 2016-08-17 01:38:48.441
aited for process J000 to be spawned for 100 seconds
** 2016-08-17 01:38:58.451
aited for process J000 to be spawned for 110 seconds
** 2016-08-17 01:56:44.526

幾乎都是1:30左右發生的,很有意思的是錯誤出現的時間(工廠系統管理員反饋Symantec BE 收取RMAN備份的那個作業開始異常的時間也剛剛是13號出現,白天我去測試作業收帶,發現又都是正常的,當時一直按照官方文檔https://www.veritas.com/support/en_US/article.TECH73015在排除、驗證),現在看來很有可能Symantec BE作業的異常也是這個引起的。檢查了RMAN的備份記錄,幾乎在12:00到12:40直接就已經操作完成了。 J000一般為作業的進程。檢查了一下,僅僅是一個系統收集統計信息的作業在這個時間點運行。暫且看不出什麼問題。

關於Waited for process xxx to be spawned for xxx seconds, 在oracle metalink看到下面有意思的資料:

You need to review both the traditional as well as incident trace files to understand the load on the system and major waits on the database. Typically
 
The incident trace file will show you the database wide waits that the child process encountering when coming up.
The traditional trace file will show you the details of the load on the machine (below ones):
Load average
Memory consumption
Output of PS (process state)
Output of GDB (to view the function stack)
In order to investigate the issue, it might also help to understand the general stages of the process startup:
 
Queued phase
Forking Phase
Execution Phase
Initialization phase
In general, the forking and execution phases are directly linked to system load and resources. To check what phase the process startup is, open the traditional trace file (not incident) and look for the wording "Waited for process"
 
Waited for process XYZ to be spawned for nnn seconds
Waited for process XYZ to initialize for nnn seconds
 
If the message contains "to be spawned", it means the process is still at queued or forking phase (1 & 2)
If the message contains "to initialize", it means the process is at execution or Initialize phase (3 & 4)
 
Other useful information can be obtained from the trace files:
 
Open the traditional trace file and review the section which starts with 'Process diagnostic dump for' - 'load average','memory information','process state - ps output' and also 'gdb output' will provide initial insight on the load on the system.
Open the incident trace file and find the section 'PROCESS STATE' and within that section look for 'Current Wait Stack'. This will provide the database wide events that the child process encountered and may provide clues and generic direction on how to proceed.
 
Why does the error occur? - Potential causes and solutions/actions
 
The root cause of this issue mainly falls under the following 2 categories.
Contention among processes: The process which is coming up might require resources that are actually being contended for by different other processes and sometimes the parent process itself might contend for the same resource as the child process (indirectly).
OS and network level issues: The machine on which this is happening might be CPU/memory saturated and this may delay the process spawning. Network latency when your storage is on a network file system may also delay the process spawning.
Some of the common known issues and potential solutions are listed below:
 
Lack of OS resources or incorrect configuration
This error may be observed due to lack of OS resources or incorrect configuration, typically memory or swap space may be insufficient to spawn a new process. 
Accordingly, the following checks may help to identify the issue:
Check OS Error Log file for the time when the error is generated
OS Messages log can provide an indication whether there is a problem with the Operating System Itself
* AIX: the output of the "errpt" command and the "errpt -a" command 
* Linux: /var/log/messages
* Solaris: /var/adm/messages
* HP-UX: /var/adm/syslog/syslog.log
* Tru64: /var/adm/messages
* Windows: Save Application Log and System Log as txt files Using Event Viewer
Run HCVE script 
The HCVE script verifies whether OS resources are set as recommended by Oracle. Instructions on how to download and run the script are outlined in Document 250262.1.
Please note, that the script will only check whether your system is configured as per the recommended 'minimum' values. Depending on your environment these values may not be sufficient though.
Run OS Watcher 
OS Watcher is an Oracle tool that allows you to monitor the system from an OS perspective. Document 301137.1 outlines the usage of this tool.
Check the defined user limitation (ulimit) settings (UNIX-only)
Check the ulimit settings as the oracle user (or the owner of the oracle software) using 
# ulimit -a
Minimum values can be found in Document 169706.1.
Please note, that the values mentioned in the note are bare minimum values for a standard environment. Depending on your environment setup, you may need to increase these values accordingly.
Recommended actions:
 
Review the resource-related suggestions as reported from the output of the HCVE script and make changes accordingly. The following 2 articles may help in understanding these suggestion better:
Document 169706.1: Oracle Database on Unix AIX,HP-UX,Linux,Mac OS X,Solaris,Tru64 Unix Operating Systems Installation and Configuration Requirements Quick Reference (8.0.5 to 11.2)
Document 225349.1: Address Windowing Extensions (AWE) or VLM on Windows Platforms
(Typically on windows-system with more than 4Gb of RAM, enabling the /3GB switch in the boot.ini is required)
Check the define user limitation (ulimit) settings (UNIX-only)
 
ASLR LINUX feature is being used
ASLR is a feature that is activated by default on some of the newer LINUX distributions. It is designed to load shared memory objects in random addresses. In Oracle, multiple processes map a shared memory object at the same address across the processes. With ASLR turned on, Oracle cannot guarantee the availability of this shared memory address. This conflict in the address space means that a process trying to attach a shared memory object to a specific address may not be able to do so, resulting in a failure in SHMAT subroutine.
This problem is mainly reported in Redhat 5 and Oracle 11.2.0.2. You can verify whether ASLR is being used as follows:
# /sbin/sysctl -a | grep randomize
kernel.randomize_va_space = 1
-> If the parameter is set to any value other than 0 then ASLR is in use.
 
Recommended actions:
Disable the use of the ASLR Feature. 
On Redhat 5, to permanently disable ASLR, add/modify this parameter in /etc/sysctl.conf
 
kernel.randomize_va_space=0
kernel.exec-shield=0
 
You need to reboot, for kernel.exec-shield parameter to take effect. 
Note that both kernel parameters are required for ASLR to be switched off.
 
Incorrect Database Settings
Check whether PGA_AGGREGATE_TARGET is set to TRUE/FALSE
The parameter PGA_AGGREGATE_TARGET is a numeric value and not a Boolean value and therefore must be set to a number for it to function correctly.
Check whether PRE_PAGE_SGA is set to TRUE
PRE_PAGE_SGA instructs Oracle to read the entire SGA into active memory at instance startup. Operating system page table entries are then prebuilt for each page of the SGA. This setting can increase the amount of time necessary for instance startup, but it is likely to decrease the amount of time necessary for Oracle to reach its full performance capacity after startup. PRE_PAGE_SGA can increase the process startup duration, because every process that starts must access every page in the SGA, this can cause the PMON process to take longer to start and exceed the timeout which is by default 120 seconds causing the instance startup to fail.
Check output of SQL> select * from v$resource_limit;
V$resource_limit dynamic view provides the details of resources like sessions, processes, locks etc. It has the initialization values for the resources, maximum limit reached after the last database startup and current utilization of the resource.
Recommended actions:
 
Properly set PGA_AGGREGATE_TARGET to a numeric value.
Set PRE_PAGE_SGA to FALSE (recommended).
Check if limits were reached and accordingly increase the value of the resource in concern.
 
Other Causes or Known Issues
Other potential causes known to cause issues could be
Too much activity on your machine
NFS latency issues
Disk latency issue (that affects I/O)
Network latency
 
Recommended actions:
 
Since almost all these reasons are not related to the RDBMS itself, it is recommended you involve your Network, Storage and System Administrators in this investigation. 

也就是說J000這個進程老是在forking phase要花很長時間排隊。上面資料也介紹了發生這種錯誤的場景,我們先檢查一下系統資源是否存在不足的情況。

# sar -r

如上所示,內存各項指標不大,CPU利用率在這個時間段確實有所上升。但是總體來說,還是非常低的。

$sar -u

於是我們檢查系統的message日志,如下所示,發現這個時間點出現了"INFO: task bdi-default:40 blocked for more than 120 seconds"錯誤(當然13-17號,只有17號出現了這個錯誤):

Aug 17 01:32:13 localhost kernel: INFO: task bdi-default:40 blocked for more than 120 seconds.
Aug 17 01:32:13 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 17 01:32:13 localhost kernel: bdi-default   D 0000000000000000     0    40      2 0x00000000
Aug 17 01:32:13 localhost kernel:  ffff88042e7b5bf0 0000000000000046 0000000000000000 ffff88042e5a8080
Aug 17 01:32:13 localhost kernel:  ffff88042e7b2340 ffffffff81aa84c0 ffff88042e7b2710 0000000547046b50
Aug 17 01:32:13 localhost kernel:  0000000000000001 0000000000000000 0000000000000000 7fffffffffffffff
Aug 17 01:32:13 localhost kernel: Call Trace:
Aug 17 01:32:13 localhost kernel:  [<ffffffff814527e9>] schedule_timeout+0x36/0xe7
Aug 17 01:32:13 localhost kernel:  [<ffffffff8102bc30>] ? flat_send_IPI_mask+0x11/0x13
Aug 17 01:32:13 localhost kernel:  [<ffffffff8104367e>] ? need_resched+0x23/0x2d
Aug 17 01:32:13 localhost kernel:  [<ffffffff8145265b>] wait_for_common+0xb7/0x12c
Aug 17 01:32:13 localhost kernel:  [<ffffffff8104cf2f>] ? default_wake_function+0x0/0x19
Aug 17 01:32:13 localhost kernel:  [<ffffffff81452773>] wait_for_completion+0x1d/0x1f
Aug 17 01:32:13 localhost kernel:  [<ffffffff81076aab>] kthread_create+0x9c/0x143
Aug 17 01:32:13 localhost kernel:  [<ffffffff810edce9>] ? bdi_start_fn+0x0/0xd1
Aug 17 01:32:13 localhost kernel:  [<ffffffff810654cb>] ? lock_timer_base+0x2b/0x4f
Aug 17 01:32:13 localhost kernel:  [<ffffffff81065562>] ? try_to_del_timer_sync+0x73/0x81
Aug 17 01:32:13 localhost kernel:  [<ffffffff81065589>] ? del_timer_sync+0x19/0x26
Aug 17 01:32:13 localhost kernel:  [<ffffffff8145286a>] ? schedule_timeout+0xb7/0xe7
Aug 17 01:32:13 localhost kernel:  [<ffffffff81065596>] ? process_timeout+0x0/0x10
Aug 17 01:32:13 localhost kernel:  [<ffffffff810edf8b>] bdi_forker_task+0x1d1/0x263
Aug 17 01:32:13 localhost kernel:  [<ffffffff8103feee>] ? __wake_up_common+0x46/0x79
Aug 17 01:32:13 localhost kernel:  [<ffffffff810eddba>] ? bdi_forker_task+0x0/0x263
Aug 17 01:32:13 localhost kernel:  [<ffffffff810eddba>] ? bdi_forker_task+0x0/0x263
Aug 17 01:32:13 localhost kernel:  [<ffffffff81076a07>] kthread+0x6e/0x76
Aug 17 01:32:13 localhost kernel:  [<ffffffff81012dea>] child_rip+0xa/0x20
Aug 17 01:32:13 localhost kernel:  [<ffffffff81076999>] ? kthread+0x0/0x76
Aug 17 01:32:13 localhost kernel:  [<ffffffff81012de0>] ? child_rip+0x0/0x20
Aug 17 01:34:13 localhost kernel: INFO: task bdi-default:40 blocked for more than 120 seconds.
Aug 17 01:34:13 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug 17 01:34:13 localhost kernel: bdi-default   D 0000000000000000     0    40      2 0x00000000
Aug 17 01:34:13 localhost kernel:  ffff88042e7b5bf0 0000000000000046 0000000000000000 ffff88042e5a8080
Aug 17 01:34:13 localhost kernel:  ffff88042e7b2340 ffffffff81aa84c0 ffff88042e7b2710 0000000547046b50
Aug 17 01:34:13 localhost kernel:  0000000000000001 0000000000000000 0000000000000000 7fffffffffffffff
Aug 17 01:34:13 localhost kernel: Call Trace:
Aug 17 01:34:13 localhost kernel:  [<ffffffff814527e9>] schedule_timeout+0x36/0xe7
Aug 17 01:34:13 localhost kernel:  [<ffffffff8102bc30>] ? flat_send_IPI_mask+0x11/0x13
Aug 17 01:34:13 localhost kernel:  [<ffffffff8104367e>] ? need_resched+0x23/0x2d
Aug 17 01:34:13 localhost kernel:  [<ffffffff8145265b>] wait_for_common+0xb7/0x12c
Aug 17 01:34:13 localhost kernel:  [<ffffffff8104cf2f>] ? default_wake_function+0x0/0x19
Aug 17 01:34:13 localhost kernel:  [<ffffffff81452773>] wait_for_completion+0x1d/0x1f
Aug 17 01:34:13 localhost kernel:  [<ffffffff81076aab>] kthread_create+0x9c/0x143
Aug 17 01:34:13 localhost kernel:  [<ffffffff810edce9>] ? bdi_start_fn+0x0/0xd1
Aug 17 01:34:13 localhost kernel:  [<ffffffff810654cb>] ? lock_timer_base+0x2b/0x4f
Aug 17 01:34:13 localhost kernel:  [<ffffffff81065562>] ? try_to_del_timer_sync+0x73/0x81
Aug 17 01:34:13 localhost kernel:  [<ffffffff81065589>] ? del_timer_sync+0x19/0x26
Aug 17 01:34:13 localhost kernel:  [<ffffffff8145286a>] ? schedule_timeout+0xb7/0xe7
Aug 17 01:34:13 localhost kernel:  [<ffffffff81065596>] ? process_timeout+0x0/0x10
Aug 17 01:34:13 localhost kernel:  [<ffffffff810edf8b>] bdi_forker_task+0x1d1/0x263
Aug 17 01:34:13 localhost kernel:  [<ffffffff8103feee>] ? __wake_up_common+0x46/0x79
Aug 17 01:34:13 localhost kernel:  [<ffffffff810eddba>] ? bdi_forker_task+0x0/0x263
Aug 17 01:34:13 localhost kernel:  [<ffffffff810eddba>] ? bdi_forker_task+0x0/0x263
Aug 17 01:34:13 localhost kernel:  [<ffffffff81076a07>] kthread+0x6e/0x76
Aug 17 01:34:13 localhost kernel:  [<ffffffff81012dea>] child_rip+0xa/0x20
Aug 17 01:34:13 localhost kernel:  [<ffffffff81076999>] ? kthread+0x0/0x76
Aug 17 01:34:13 localhost kernel:  [<ffffffff81012de0>] ? child_rip+0x0/0x20
Aug 17 01:36:13 localhost kernel: INFO: task bdi-default:40 blocked for more than 120 seconds.
Aug 17 01:36:13 localhost kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

關於bdi-defualt進程,我從Linux內核進程詳解之二:bdi-default這篇文章摘取了下面一段:

bdi,即是backing device info的縮寫,根據英文單詞全稱可知其通指備用存儲設備相關描述信息,這在內核代碼裡用一個結構體backing_dev_info來表示:http://lxr.linux.no/#linux+v2.6.38.8/include/linux/backing-dev.h#L62

bdi,備用存儲設備,簡單點說就是能夠用來存儲數據的設備,而這些設備存儲的數據能夠保證在計算機電源關閉時也不丟失。這樣說來,軟盤存儲設備、光驅存儲設備、USB存儲設備、硬盤存儲設備都是所謂的備用存儲設備(後面都用bdi來指示),而內存顯然不是,具體看下面這個鏈接:http://www.gordonschools.aberdeenshire.sch.uk/Departments/Computing/StandardGrade/SystemsWeb/6BackingStorage.htm

相對於內存來說,bdi設備(比如最常見的硬盤存儲設備)的讀寫速度是非常慢的,因此為了提高系統整體性能,Linux系統對bdi設備的讀寫內容進行了緩沖,那些讀寫的數據會臨時保存在內存裡,以避免每次都直接操作bdi設備,但這就需要在一定的時機(比如每隔5秒、髒數據達到的一定的比率等)把它們同步到bdi設備,否則長久的呆在內存裡容易丟失(比如機器突然宕機、重啟),而進行間隔性同步工作的進程之前名叫pdflush,但後來在Kernel 2.6.2x/3x(沒注意具體是哪個小版本的改動,比如:http://kernelnewbies.org/Linux_2_6_35#head-57d43d498509746df08f48b1f040d20d88d2b984,http://lwn.net/Articles/396757/)對此進行了優化改進,產生有多個內核進程,bdi-default、flush-x:y等

檢查確認如下

# ps -ef | grep bdi-default | grep 40
root        40     2  0 Jan17 ?        00:00:31 [bdi-default]
root      4026   752  0 17:07 pts/3    00:00:00 grep bdi-default

看來確實是這個bdi-default進程的異常引起的。接下來就需要查證為什麼出現“task bdi-default:40 blocked for more than 120 seconds”,關於這個網上有很多資料:

由於bug引起的(與我們的環境不符,直接pass)

Slow writes to ext4 partition - INFO: task flush-253:7:2137 blocked for more than 120 seconds

我自己也遇到過幾次,不過是不同的進程引起的,也有所區別。

TNS-12518 & Linux Error:32:Broken pipe

Linux服務器宕機案例第二則

在官方資料有介紹,但是我無訂閱賬號,無法查看具體內容。

https://access.redhat.com/solutions/31453

在System becomes unresponsive with message “INFO: task : blocked for more than 120 seconds裡面有如下介紹

INFO: task <process>:<pid> blocked for more than 120 seconds

What is the reason behind above messages and what kind of information is needed to troubleshoot them?

  1. These messages typically mean that the system is experiencing disk or memory congestion and processes are being starved of available resources.
  2. These messages serve as a warning that something may not be operating optimally. They do not necessarily indicate a serious problem and any blocked processes should eventually proceed when the system recovers.
  3. To troubleshoot further, generate a vmcore
  4. If the hung task is a third-party application, please engage the application vendor in the issue meanwhile.
  5. If the hung task messages are known to be erroneous, they can be disabled. This is not advised, and it will not prevent any hangs. To disable the messages, use
  1. sysctl kernel.hung_task_timeout_secs=0
  1. If it causes the crash and the causes are known to be erroneous, please disable it by putting the below in /etc/sysctl.conf. Once have the below value in the file, please run ‘sysctl -p’ to apply the change.
  1. kernel.hung_task_panic = 0

Root Cause:

The khungtaskd kernel thread monitors the process states and checks if there are any processes stuck in uninterruptible state for the period set in “kernel.hung_task_timeout_secs” sysctl parameter (default is 120 seconds). If so it will log the message along with a call trace of the process that is blocked. The hung task watchdog will by default only report the first 10 instances of detected hung tasks and then will disable reporting. This is to prevent the system log from being flooded with messages. This means that even though no more blocked task messages are being reported there may still be processes becoming stuck for long periods

Cautions:

  1. If hung_task_panic is enabled, this can cause false positives to unnecessarily panic your machine.

o Although usually, a task being blocked for > 2 minutes is a good indication that something has gone wrong inside the kernel, there are circumstances in which a task can be legitimately blocked for this long, for example:

o flushing large amounts of file system data to a slow device duringumount() or sync() can take a longer than the defaulthung_task_timeout_secs

o while the default hung_task_timeout_secs is 2x the default IO timeout value, different types of devices and different environments can change the default IO timeout value causing false hung task event triggers as well as panics if hung_task_panic is enabled.

  1. As a general rule, the hung_task_timeout_secs should be set to a value larger than the longest expected IO timeout value to prevent false triggering of the stall task logic and its event output within messages. This is especially true ifhung_task_panic is enabled as false triggering of the stalled task logic will cause induced kernel panics.

打算先重啟觀察一下,如果不行再試試設置kernel.hung_task_panic = 0,結果昨天重啟過後,一切正常了。真懷疑是VMware環境在某些條件下觸發的一個bug!

參考資料:

http://www.lenky.info/archives/2012/02/1125

https://www.blackmoreops.com/2014/09/22/linux-kernel-panic-issue-fix-hung_task_timeout_secs-blocked-120-seconds-problem/

http://www.cnblogs.com/kerrycode/p/4164838.html

http://www.cnblogs.com/kerrycode/p/5653586.html

https://linuxraj.wordpress.com/2015/11/17/system-becomes-unresponsive-with-message-info-task-blocked-for-more-than-120-seconds/

https://support.oracle.com/epmos/faces/DocumentDisplay?_afrLoop=359621643018467&id=1989698.1&displayIndex=7&_afrWindowMode=0&_adf.ctrl-state=s96s1un90_182#title1

https://bugzilla.redhat.com/show_bug.cgi?id=652262

http://xxxxxx/Linuxjc/1151021.html TechArticle

Copyright © Linux教程網 All Rights Reserved