Linux 日志报错 xxx blocked for more than 120 seconds

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

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. 

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.

# 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