Why oracle RMAN full backup always hasn't been finished yet in recent two number of Sunday?

tbm-oracle1:/home/oracle/$free -g
> total used free shared buffers
> cached
> Mem: 503 266 237 256 0 257
> -/+ buffers/cache: 8 495
> Swap: 15 0 15
>

select inst_id,
> 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#||'_at_'||a.inst_id, '
> <- ') tree,
> level as tree_level
> from gv$session a
> start with a.blocking_session is not null
> connect by (a.sid||'_at_'||a.inst_id) = prior
> (a.blocking_session||'_at_'||a.blocking_instance)
> ) t
> where sql_id is null
> order by tree_level asc;
>
> 1 1139 1731 log file sync ACTIVE <- 1139,1731_at_1 1
> 1 1140 3195 log file sync ACTIVE <- 1140,3195_at_1 1
> 1 1142 1171 log file sync ACTIVE <- 1142,1171_at_1 1
> 1 1280 2131 log file sync ACTIVE <- 1280,2131_at_1 1
> 1 1423 3205 log file sync ACTIVE <- 1423,3205_at_1 1
> 1 1424 2935 log file sync ACTIVE <- 1424,2935_at_1 1
> ......
> 1 998 2211 log file sync ACTIVE <- 998,2211_at_1 1
> 1 999 3507 log file sync ACTIVE <- 999,3507_at_1 1
> 1 2557 1 log file parallel write ACTIVE <- 8240,1605_at_1 <- 2557,1_at_1 2
> 1 2557 1 log file parallel write ACTIVE <- 8381,1607_at_1 <- 2557,1_at_1 2
> 1 2557 1 log file parallel write ACTIVE <- 8382,2235_at_1 <- 2557,1_at_1 2
> 1 2557 1 log file parallel write ACTIVE <- 8524,1967_at_1 <- 2557,1_at_1 2
> 1 2557 1 log file parallel write ACTIVE <- 8525,2467_at_1 <- 2557,1_at_1 2
> 1 2557 1 log file parallel write ACTIVE <- 857,2215_at_1 <- 2557,1_at_1 2
> ......
> 1 2557 1 log file parallel write ACTIVE <- 3555,25_at_1 <- 4408,13_at_1 <-
> 2557,1_at_1 3
> 1 2557 1 log file parallel write ACTIVE <- 3838,1783_at_1 <- 4408,13_at_1 <-
> 2557,1_at_1 3
> 1 2557 1 log file parallel write ACTIVE <- 4692,25_at_1 <- 4408,13_at_1 <-
> 2557,1_at_1 3
> 1 2557 1 log file parallel write ACTIVE <- 5113,1655_at_1 <- 4408,13_at_1 <-
> 2557,1_at_1 3
> 1 2557 1 log file parallel write ACTIVE <- 5545,7_at_1 <- 4408,13_at_1 <-
> 2557,1_at_1 3
>

select p.spid, s.sid, s.serial#, s.machine, s.program
> 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_at_tbm-oracle1 (LGWR)*
>

vi xhsddb_lgwr_5232.trc
> ......
> *** 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
>

tbm-oracle1:/home/oracle$ sar
> 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

vi /var/log/message
> ......
> *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

......

tbm-oracle1:/home/oracle/$ps -ef | grep 3767
> 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
>

 Afterwards I've found this note -
*https://blog.csdn.net/xyz846/article/details/81872638* <https://blog.csdn.net/xyz846/article/details/81872638>.

Yes, I've finished setting "vm.dirty_background_ratio = 5 and vm.dirty_ratio = 10" in /etc/sysctl.conf once (in other words on Aug 09, 2022 occured the same issue but after 3 months it also appeared ...).

[root_at_tbm-oracle1 ~]# cat /etc/sysctl.conf
> ......
> vm.dirty_background_ratio = 5
> vm.dirty_ratio = 10
> ......

Now it seems like to have no any effect in previous setting.

Has anyboby else other good suggestion? Thank you so much.

Best Regards
Quanwen Zhao

--
http://www.freelists.org/webpage/oracle-l