Hello my oracle friends :-),
My client has a oracle database 11.2.0.4.0 (os is RedHat 6.9) that deployed
on virtual machine server. This issue is very weird. The oracle RMAN full
backup always hasn't been finished yet in recent two number of Sunday (but
incremental rman backup is good and only need less than 1 hour or even just
10 minutes to finish).
The volume of rman full backup has approximately 1.2 TB and it took 8 hours
finishing backup in each Sunday (the crontab has started from 01:00 every
day).
But the rman full backup hasn't been finished yet both on Nov 20 and 27,
2022.
Here is some data I've captured.
tbm-oracle1:/home/oracle$w
07:36:21 up 1 day, 22:39, 5 users, load average: *66.10, 66.04, 65.63*
USER TTY FROM LOGIN@ IDLE JCPU PCPU WHAT
root pts/2 192.168.254.6 07:11 23:30 0.00s 0.00s -bash
root pts/3 192.168.254.6 07:13 23:01 0.01s 0.01s -bash
root pts/4 192.168.254.6 07:17 3.00s 0.03s 0.01s w
total used free shared buffers
cached
Mem: 503 266 237 256 0 257
-/+ buffers/cache: 8 495
Swap: 15 0 15
sid,
serial,
event,
status,
tree,
tree_level
from (select a.inst_id,
a.sid,
a.serial# as serial,
a.sql_id,
a.event,
a.status,
connect_by_isleaf as isleaf,
sys_connect_by_path(a.sid||','||a.serial#||'@'||a.inst_id, '
<- ') tree,
level as tree_level
from gv$session a
start with a.blocking_session is not null
connect by (a.sid||'@'||a.inst_id) = prior
(a.blocking_session||'@'||a.blocking_instance)
) t
where sql_id is null
order by tree_level asc;
1 1139 1731 log file sync ACTIVE <- 1139,1731@1 1
1 1140 3195 log file sync ACTIVE <- 1140,3195@1 1
1 1142 1171 log file sync ACTIVE <- 1142,1171@1 1
1 1280 2131 log file sync ACTIVE <- 1280,2131@1 1
1 1423 3205 log file sync ACTIVE <- 1423,3205@1 1
1 1424 2935 log file sync ACTIVE <- 1424,2935@1 1
......
1 998 2211 log file sync ACTIVE <- 998,2211@1 1
1 999 3507 log file sync ACTIVE <- 999,3507@1 1
1 2557 1 log file parallel write ACTIVE <- 8240,1605@1 <- 2557,1@1 2
1 2557 1 log file parallel write ACTIVE <- 8381,1607@1 <- 2557,1@1 2
1 2557 1 log file parallel write ACTIVE <- 8382,2235@1 <- 2557,1@1 2
1 2557 1 log file parallel write ACTIVE <- 8524,1967@1 <- 2557,1@1 2
1 2557 1 log file parallel write ACTIVE <- 8525,2467@1 <- 2557,1@1 2
1 2557 1 log file parallel write ACTIVE <- 857,2215@1 <- 2557,1@1 2
......
1 2557 1 log file parallel write ACTIVE <- 3555,25@1 <- 4408,13@1 <-
2557,1@1 3
1 2557 1 log file parallel write ACTIVE <- 3838,1783@1 <- 4408,13@1 <-
2557,1@1 3
1 2557 1 log file parallel write ACTIVE <- 4692,25@1 <- 4408,13@1 <-
2557,1@1 3
1 2557 1 log file parallel write ACTIVE <- 5113,1655@1 <- 4408,13@1 <-
2557,1@1 3
1 2557 1 log file parallel write ACTIVE <- 5545,7@1 <- 4408,13@1 <-
2557,1@1 3
from v$process p, v$session s
where p.addr = s.paddr
and (s.sid=2557 and s.serial#=1);
*5232 2557 1 tbm-oracle1 oracle@tbm-oracle1 (LGWR)*
......
*** 2022-11-27 01:02:25.763
Warning: log write elapsed time 1301ms, size 1KB
*** 2022-11-27 01:02:28.646
Warning: log write elapsed time 856ms, size 2KB
*** 2022-11-27 01:02:30.598
Warning: log write elapsed time 1144ms, size 2KB
*** 2022-11-27 01:02:33.065
Warning: log write elapsed time 912ms, size 112KB
*** 2022-11-27 01:02:41.558
Warning: log write elapsed time 511ms, size 474KB
*** 2022-11-27 01:12:47.215
*WARNING:io_getevents timed out 600 sec*
*** 2022-11-27 01:22:47.215
WARNING:io_getevents timed out 600 sec
*** 2022-11-27 01:32:47.215
WARNING:io_getevents timed out 600 sec
Linux 4.1.12-61.1.28.el6uek.x86_64 (tbm-oracle1) 11/27/2022
_x86_64_ (64 CPU)
12:00:01 AM CPU %user %nice %system %iowait %steal
%idle
12:10:01 AM all 0.73 0.00 0.12 0.32 0.03
98.81
12:20:01 AM all 0.45 0.00 0.08 0.04 0.02
99.41
12:30:01 AM all 0.50 0.00 0.07 0.04 0.02
99.36
12:40:01 AM all 0.46 0.00 0.07 0.06 0.02
99.38
12:50:01 AM all 0.43 0.00 0.07 0.05 0.02
99.43
01:00:01 AM all 0.49 0.00 0.07 * 0.03* 0.02
99.38
01:10:01 AM all 0.78 0.00 0.14 *10.97* 0.05
88.06
01:20:01 AM all 0.64 0.00 0.09 6.19 0.02
93.06
01:30:01 AM all 0.40 0.00 0.07 6.22 0.02
93.29
01:40:01 AM all 0.33 0.00 0.07 8.94 0.02
90.65
01:50:01 AM all 0.31 0.00 0.07 9.31 0.01
90.30
02:00:01 AM all 0.37 0.00 0.08 9.91 0.02
89.62
02:10:02 AM all 0.41 0.00 0.09 10.84 0.02
88.64
02:20:01 AM all 0.26 0.00 0.07 10.89 0.02
88.76
02:30:01 AM all 0.26 0.00 0.07 10.91 0.01
88.75
02:40:01 AM all 0.26 0.00 0.06 10.91 0.01
88.76
02:50:01 AM all 0.27 0.00 0.07 10.88 0.01
88.78
03:00:01 AM all 0.26 0.00 0.07 10.90 0.01
88.76
03:10:01 AM all 0.30 0.00 0.07 10.90 0.01
88.71
03:20:01 AM all 0.27 0.00 0.07 10.90 0.01
88.76
03:30:01 AM all 0.26 0.00 0.06 10.87 0.01
88.80
03:40:01 AM all 0.27 0.00 0.07 10.88 0.01
88.77
03:50:01 AM all 0.26 0.00 0.07 10.89 0.01
88.77
04:00:01 AM all 0.25 0.00 0.06 10.88 0.01
88.79
04:10:01 AM all 0.30 0.00 0.07 10.79 0.01
88.82
04:20:01 AM all 0.26 0.00 0.06 10.84 0.01
88.82
04:30:01 AM all 0.26 0.00 0.07 10.87 0.01
88.79
04:40:01 AM all 0.26 0.00 0.06 10.89 0.01
88.77
04:50:01 AM all 0.25 0.00 0.07 10.89 0.01
88.77
05:00:01 AM all 0.25 0.00 0.07 10.89 0.01
88.78
05:10:01 AM all 0.28 0.00 0.07 10.91 0.01
88.74
05:20:01 AM all 0.27 0.00 0.07 10.89 0.01
88.75
05:30:01 AM all 0.26 0.00 0.07 10.89 0.01
88.76
05:40:01 AM all 0.26 0.00 0.07 10.89 0.01
88.77
05:50:01 AM all 0.26 0.00 0.07 10.90 0.01
88.76
06:00:01 AM all 0.26 0.00 0.07 10.86 0.01
88.79
06:10:01 AM all 0.28 0.00 0.07 10.87 0.01
88.76
06:20:01 AM all 0.26 0.00 0.07 10.89 0.01
88.78
06:30:01 AM all 0.26 0.00 0.06 10.87 0.01
88.80
06:40:01 AM all 0.26 0.00 0.07 10.87 0.01
88.79
06:50:01 AM all 0.26 0.00 0.06 10.88 0.01
88.78
07:00:01 AM all 0.26 0.00 0.07 10.88 0.01
88.77
07:10:01 AM all 0.30 0.00 0.07 10.89 0.01
88.72
07:20:01 AM all 0.28 0.00 0.06 10.89 0.01
88.75
07:30:01 AM all 0.26 0.00 0.07 10.89 0.01
88.76
Average: all 0.33 0.00 0.07 9.14 0.02
90.45
......
*Nov 27 01:05:21 tbm-oracle1 kernel: [144482.973094] INFO: task
jbd2/dm-3-8:3767 blocked for more than 120 seconds.*
Nov 27 01:05:21 tbm-oracle1 kernel: [144482.989351] Not tainted
4.1.12-61.1.28.el6uek.x86_64 #2
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.000720] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001051] jbd2/dm-3-8 D
ffff887e0cb976c0 0 3767 2 0x00000000
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001057] ffff887dccfaf778
0000000000000046 ffff887dd56cd400 ffff887ddaaa8e00
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001060] 0000000000000001
ffff887dccfac008 ffff887e0cb976c0 7fffffffffffffff
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001062] ffff887dd8dfc300
ffffe8fffed80280 ffff887dccfaf798 ffffffff816c790e
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001065] Call Trace:
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001075] [<ffffffff816c790e>]
schedule+0x3e/0x90
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001078] [<ffffffff816ca7e5>]
schedule_timeout+0x1b5/0x210
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001083] [<ffffffff8100c1e9>]
? xen_clocksource_get_cycles+0x9/0x10
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001084] [<ffffffff8100bfc5>]
? xen_clocksource_read+0x15/0x20
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001086] [<ffffffff8100c1e9>]
? xen_clocksource_get_cycles+0x9/0x10
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001091] [<ffffffff810f5792>]
? ktime_get+0x52/0xc0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001094] [<ffffffff816c6f04>]
io_schedule_timeout+0xa4/0x110
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001099] [<ffffffff812f9ef1>]
bt_get+0x151/0x1f0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001103] [<ffffffff810c8470>]
? wait_woken+0x90/0x90
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001106] [<ffffffff812f9ffc>]
blk_mq_get_tag+0x6c/0xc0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001119] [<ffffffff812f554e>]
__blk_mq_alloc_request+0x1e/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001128] [<ffffffff812f6a50>]
blk_mq_map_request+0x1b0/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001139] [<ffffffff812f7887>]
blk_sq_make_request+0x97/0x3e0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001153] [<ffffffff812eb440>]
generic_make_request+0xc0/0x100
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001156] [<ffffffff812eb4ff>]
submit_bio+0x7f/0x160
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001158] [<ffffffff812e436a>]
? bio_alloc_bioset+0xba/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001163] [<ffffffff8123b55a>]
_submit_bh+0x13a/0x190
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001166] [<ffffffff8123b5c0>]
submit_bh+0x10/0x20
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001169] [<ffffffff8123b90f>]
write_dirty_buffer+0x5f/0x80
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001185] [<ffffffffa00a45af>]
flush_descriptor+0xaf/0xe0 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001194] [<ffffffff811e5fde>]
? kmem_cache_free+0x1ee/0x210
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001205] [<ffffffffa00a4861>]
jbd2_journal_write_revoke_records+0xf1/0x140 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001210] [<ffffffffa00a0dee>]
jbd2_journal_commit_transaction+0x4ae/0x1820 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001214] [<ffffffff810bab7d>]
? update_curr+0x13d/0x1f0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001217] [<ffffffff81015982>]
? __switch_to+0x212/0x5e0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001228] [<ffffffff810ed47c>]
? lock_timer_base+0x3c/0x70
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001235] [<ffffffffa00a6df7>]
kjournald2+0x127/0x340 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001240] [<ffffffff810c8470>]
? wait_woken+0x90/0x90
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001246] [<ffffffffa00a6cd0>]
? jbd2_journal_clear_features+0x90/0x90 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001254] [<ffffffffa00a6cd0>]
? jbd2_journal_clear_features+0x90/0x90 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001260] [<ffffffff810a46de>]
kthread+0xce/0xf0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001263] [<ffffffff810a4610>]
? kthread_freezable_should_stop+0x70/0x70
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001266] [<ffffffff816cbf22>]
ret_from_fork+0x42/0x70
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001268] [<ffffffff810a4610>]
? kthread_freezable_should_stop+0x70/0x70
......
*Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001284] INFO: task
oracle:5224 blocked for more than 120 seconds.*
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001598] Not tainted
4.1.12-61.1.28.el6uek.x86_64 #2
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.001877] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002287] oracle D
ffff887e0bc176c0 0 5224 1 0x00000080
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002291] ffff887c832c33f8
0000000000000086 ffff887c849e3800 ffffffff81a914e0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002294] ffff887e0000000a
ffff887c832c0008 ffff887e0bc176c0 7fffffffffffffff
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002297] ffff887dd8dfc300
ffffe8fffde00280 ffff887c832c3418 ffffffff816c790e
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002299] Call Trace:
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002306] [<ffffffff816c790e>]
schedule+0x3e/0x90
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002309] [<ffffffff816ca7e5>]
schedule_timeout+0x1b5/0x210
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002311] [<ffffffff8100bfc5>]
? xen_clocksource_read+0x15/0x20
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002314] [<ffffffff8100c1e9>]
? xen_clocksource_get_cycles+0x9/0x10
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002317] [<ffffffff810f5792>]
? ktime_get+0x52/0xc0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002320] [<ffffffff816c6f04>]
io_schedule_timeout+0xa4/0x110
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002329] [<ffffffff812f9ef1>]
bt_get+0x151/0x1f0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002338] [<ffffffff810c8470>]
? wait_woken+0x90/0x90
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002346] [<ffffffff812f9ffc>]
blk_mq_get_tag+0x6c/0xc0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002356] [<ffffffff812f554e>]
__blk_mq_alloc_request+0x1e/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002362] [<ffffffff812f6a50>]
blk_mq_map_request+0x1b0/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002366] [<ffffffff812f7887>]
blk_sq_make_request+0x97/0x3e0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002370] [<ffffffff812eb440>]
generic_make_request+0xc0/0x100
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002372] [<ffffffff812eb4ff>]
submit_bio+0x7f/0x160
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002376] [<ffffffff81241c1a>]
do_direct_IO+0x6fa/0x1100
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002379] [<ffffffff812429d9>]
do_blockdev_direct_IO+0x3b9/0x760
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002400] [<ffffffffa00ced20>]
? ext4_get_block_write_nolock+0x20/0x20 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002405] [<ffffffffa009fdb0>]
? jbd2_journal_dirty_metadata+0x100/0x250 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002417] [<ffffffffa00ced20>]
? ext4_get_block_write_nolock+0x20/0x20 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002427] [<ffffffffa009db5a>]
? jbd2_journal_stop+0x2aa/0x500 [jbd2]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002429] [<ffffffff81242dc3>]
__blockdev_direct_IO+0x43/0x50
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002436] [<ffffffffa00ccb10>]
? ext4_invalidatepage+0xf0/0xf0 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002443] [<ffffffffa00ccdd9>]
ext4_ext_direct_IO+0x299/0x370 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002455] [<ffffffffa00ccb10>]
? ext4_invalidatepage+0xf0/0xf0 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002464] [<ffffffffa00cfdf2>]
ext4_direct_IO+0x122/0x220 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002472] [<ffffffff81188e3e>]
generic_file_direct_write+0xae/0x170
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002476] [<ffffffff81188fc3>]
__generic_file_write_iter+0xc3/0x1b0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002478] [<ffffffff810ee392>]
? del_timer_sync+0x52/0x60
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002485] [<ffffffffa00c81d6>]
ext4_file_write_iter+0x126/0x3c0 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002492] [<ffffffffa00c80b0>]
? ext4_unwritten_wait+0xb0/0xb0 [ext4]
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002495] [<ffffffff81250961>]
aio_run_iocb+0x231/0x300
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002497] [<ffffffff810bab7d>]
? update_curr+0x13d/0x1f0
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002500] [<ffffffff811bc6b3>]
? handle_pte_fault+0x193/0x230
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002503] [<ffffffff81250c86>]
io_submit_one+0x256/0x510
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002505] [<ffffffff8125107d>]
do_io_submit+0x13d/0x200
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002507] [<ffffffff81251150>]
SyS_io_submit+0x10/0x20
Nov 27 01:05:21 tbm-oracle1 kernel: [144483.002509] [<ffffffff816cbb2e>]
system_call_fastpath+0x12/0x71
root 3767 2 0 Nov25 ? 00:00:03 [jbd2/dm-3-8]
oracle 62732 57340 0 07:40 pts/2 00:00:00 grep 3767
tbm-oracle1:/home/oracle/$ps -ef | grep 5224
oracle 5224 1 0 Nov25 ? 00:01:01 ora_dbw4_xhsddb
oracle 63096 57340 0 07:42 pts/2 00:00:00 grep 5224
......
vm.dirty_background_ratio = 5
vm.dirty_ratio = 10
......
