🖥️ Database Environment:
🔹 Operating System: HP-UX 11.31
🗄️ Database Environment: Oracle Real Application Clusters (RAC)
⚙️ Database Version: Oracle Database 19c Enterprise Edition (19.26)
Problem Statement: A customer reported intermittent application slowdowns in a critical OLTP production database. During the incidents, session counts increased rapidly and multiple application modules experienced performance degradation. The customer requested a root cause analysis and recommendations to prevent future occurrences. Incident Timeline: Five short-duration performance spikes were observed: Incident 1: 09:43:11 AM to 09:43:36 AM - Duration: < 1 min Incident 2: 09:49:36 AM to 09:49:57 AM - Duration: < 1 min Incident 3: 09:58:21 AM to 09:58:45 AM - Duration: < 1 min Incident 4: 10:02:25 AM to 10:02:41 AM - Duration: < 1 min Incident 5: 10:06:23 AM to 10:06:41 AM - Duration: < 1 min Although each incident lasted less than a minute, the impact was noticeable to end users due to the sudden increase in waiting sessions. Let's troubleshoot the DB performance issue. |
Step 1: Let's examine the session activity during the one-minute spike window to understand exactly what was happening in the database and identify the root cause of the performance degradation. The script is scheduled to run on a daily basis that captures the session activity from GV$SESSION at two-second intervals. This will provide the vauable insights during performance spikes like workload patterns, resource contention, blocking sessions, and other performance bottlenecks.This information plays a key role in facilitating an effective root cause analysis. If you review the session details, you can see that the number of sessions spiked during the issue timeframe, which indicates that something abnormal occurred in the database at that time. Let's analyze the wait events and review the SQL statements executed during that period to identify any potential issues.  Session Logs: 09:42:39 427 rows selected. 09:42:42 407 rows selected. 09:42:44 444 rows selected. 09:42:47 481 rows selected. 09:42:50 456 rows selected. 09:42:52 546 rows selected. 09:42:55 860 rows selected. 09:42:58 4412 rows selected. 09:43:00 5059 rows selected. 09:43:03 5551 rows selected. 09:43:05 5967 rows selected. 09:43:08 6441 rows selected. 09:43:11 6965 rows selected. 09:43:14 7301 rows selected. 09:43:16 7686 rows selected. 09:43:21 761 rows selected. 09:43:25 714 rows selected. 09:43:28 546 rows selected. 09:43:31 532 rows selected. 09:43:34 621 rows selected. 09:43:37 431 rows selected. 09:43:39 547 rows selected. 09:43:42 460 rows selected. 09:43:45 476 rows selected. 09:43:47 487 rows selected. 09:43:50 461 rows selected. 09:49:05 490 rows selected. 09:49:08 509 rows selected. 09:49:11 555 rows selected. 09:49:14 643 rows selected. 09:49:16 583 rows selected. 09:49:19 531 rows selected. 09:49:22 550 rows selected. 09:49:25 528 rows selected. 09:49:27 541 rows selected. 09:49:30 3650 rows selected. 09:49:33 5142 rows selected. 09:49:36 5679 rows selected. 09:49:38 6098 rows selected. 09:49:41 6767 rows selected. 09:49:44 7239 rows selected. 09:49:48 7760 rows selected. 09:49:51 8467 rows selected. 09:49:57 866 rows selected. 09:50:01 829 rows selected. 09:50:06 713 rows selected. 09:50:10 669 rows selected. 09:57:59 462 rows selected. 09:58:02 548 rows selected. 09:58:05 453 rows selected. 09:58:08 444 rows selected. 09:58:10 523 rows selected. 09:58:13 443 rows selected. 09:58:16 504 rows selected. 09:58:18 3399 rows selected. 09:58:21 5303 rows selected. 09:58:24 5905 rows selected. 09:58:27 6471 rows selected. 09:58:31 7260 rows selected. 09:58:34 7795 rows selected. 09:58:37 8182 rows selected. 09:58:40 3270 rows selected. 09:58:45 846 rows selected. 09:58:49 692 rows selected. 09:58:53 621 rows selected. 09:58:56 710 rows selected. 09:59:00 525 rows selected. 10:02:09 571 rows selected. 10:02:11 496 rows selected. 10:02:14 516 rows selected. 10:02:17 520 rows selected. 10:02:19 479 rows selected. 10:02:22 4398 rows selected. 10:02:25 5223 rows selected. 10:02:27 5742 rows selected. 10:02:30 6255 rows selected. 10:02:33 6916 rows selected. 10:02:35 7406 rows selected. 10:02:38 7857 rows selected. 10:02:41 8418 rows selected. 10:02:45 2677 rows selected. 10:02:49 987 rows selected. 10:02:54 1018 rows selected. 10:02:58 811 rows selected. 10:03:01 740 rows selected. 10:03:04 610 rows selected. 10:03:06 710 rows selected. 10:05:59 477 rows selected. 10:06:02 635 rows selected. 10:06:05 556 rows selected. 10:06:07 410 rows selected. 10:06:10 500 rows selected. 10:06:13 391 rows selected. 10:06:15 337 rows selected. 10:06:18 1192 rows selected. 10:06:20 4604 rows selected. 10:06:23 5266 rows selected. 10:06:25 5751 rows selected. 10:06:28 6148 rows selected. 10:06:30 6646 rows selected. 10:06:33 7273 rows selected. 10:06:36 7746 rows selected. 10:06:39 8113 rows selected. 10:06:41 3216 rows selected. 10:06:45 950 rows selected. 10:06:48 644 rows selected. 10:06:52 732 rows selected. 10:06:56 594 rows selected. 10:07:00 514 rows selected. 10:07:03 509 rows selected. 10:07:05 578 rows selected. 10:07:08 547 rows selected. 10:07:10 496 rows selected. 10:07:13 420 rows selected. 10:07:15 399 rows selected. 10:07:18 404 rows selected. 10:07:21 447 rows selected. 10:07:23 442 rows selected. 10:07:26 606 rows selected. 10:07:28 516 rows selected. 10:07:31 461 rows selected. 10:07:33 339 rows selected. 10:07:36 337 rows selected. 10:07:38 381 rows selected. 10:07:41 428 rows selected. 10:07:43 393 rows selected. 10:07:46 326 rows selected. 10:07:48 427 rows selected. 10:07:51 430 rows selected. 10:07:53 461 rows selected. 10:07:56 489 rows selected. 10:07:58 504 rows selected. 10:08:01 452 rows selected. 10:08:04 575 rows selected. 10:08:06 505 rows selected. 10:08:09 462 rows selected. 10:08:11 439 rows selected. 10:08:14 372 rows selected. 10:08:16 355 rows selected. 10:08:19 359 rows selected. 10:08:21 356 rows selected. 10:08:24 405 rows selected. 10:08:26 383 rows selected. 10:08:29 353 rows selected. 10:08:31 439 rows selected. 10:08:34 397 rows selected. 10:08:36 408 rows selected. 10:08:39 553 rows selected. 10:08:42 545 rows selected. 10:08:44 552 rows selected. 10:08:47 401 rows selected. 10:08:49 379 rows selected. Good Time Before Issue Time:  Bad Time During Issue Period:      A comparison of session activity before, during, and after the incident reveals a distinct shift in the database wait profile.Prior to the degradation, sessions were progressing normally, with 'gc current request' representing the predominant activity and no evidence of a common blocking session. During the impacted period, however, a significant number of sessions originating from both appser1 and webser were observed waiting on the 'log file sync' wait event. Notably, all affected sessions were blocked by the same session, SID 3091, on DB Node8. Further investigation confirmed that SID 3091 corresponds to the Oracle Log Writer (LGWR) background process. What should be the next course of action, and what areas need to be investigated further? Step 2: Let's check the LGWR latency from log writer traces across all the DB nodes. This will help confirm whether the issue originated from the redo write path, storage subsystem, or an underlying infrastructure latency affecting LGWR. Node8: .......... ** 2026-06-07T09:43:17.711694+05:30 Warning: log write elapsed time 22405ms, size 8KB *** 2026-06-07T09:49:51.715261+05:30 Warning: log write elapsed time 22802ms, size 31KB *** 2026-06-07T09:58:39.629990+05:30 Warning: log write elapsed time 22695ms, size 27KB *** 2026-06-07T10:02:42.642260+05:30 Warning: log write elapsed time 22250ms, size 13KB *** 2026-06-07T10:06:40.654322+05:30 Warning: log write elapsed time 23134ms, size 28KB ......... From the LGWR trace files across all nodes, we can clearly observe an unusually high write latency of approximately 22 seconds, which is critical for an OLTP production database. This behavior was seen only on DB Node8 and consistently during above mentioned incident timestamps. Importantly, the same latency pattern was not observed on the other nodes. This strongly indicates that the issue is isolated to DB Node8 and is likely related to a node-specific redo write path or infrastructure latency affecting LGWR. Step 3: Let's generate and compare the Global AWR reports for both the good and bad periods. This comparison will help to identify any abnormalities in database activity, including changes in wait events, workload characteristics, resource utilization, interconnect traffic, I/O performance, or cluster-related issues that may have contributed to the performance degradation.       The AWR analysis shows that the log file sync issue was isolated to dbnode8 during the 09:30 to 10:15 window. Before the incident, dbnode8 was performing normally, with an average wait of 0.95 ms and 4.63% DB Time, similar to the other nodes. At 09:30, the wait time increased sharply to 8.78 ms, then rose further to 13.20 ms and eventually peaked at 16.09 ms between 09:53 and 10:15, when dbnode8 accounted for 42.32% DB Time. In contrast, the other nodes remained stable throughout, with average waits around 1.2–1.4 ms and low DB Time. An interesting observation is that the number of commit waits remained comparable across all nodes, including dbnode8. This indicates that the application workload and transaction volume did not increase significantly during the incident. Instead, each commit on dbnode8 simply took much longer to complete, pointing to increased commit latency rather than higher transactional activity. Immediately after 10:15, the instance recovered without any lasting impact. The average wait time dropped back to 1.14 ms, total wait time reduced to 3,346 seconds, and DB Time returned to 5.84%. Overall, the evidence strongly indicates a temporary bottleneck in the commit path on dbnode8, most likely involving the redo write path (LGWR), storage latency, or an instance-specific infrastructure issue. Since all other RAC nodes remained unaffected throughout the incident, the problem was localized to dbnode8 rather than being a cluster-wide or application-wide performance issue. Step 4: Let's engage a respective Storage vendor for this. This will help to review the FC port utilization and validate the health of the Fibre Channel connectivity and storage subsystem. The storage vendor has completed their analysis and confirmed that the issue was isolated to dbnode8. They identified a problem with one of the Fibre Channel (FC) cables and observed spikes on the storage side (FC Port Utilization) corresponding to the issue timeframe. Based on their findings, the storage vendor has recommended proactive replacement of the affected FC cable for DBnode8. ◉ Conclusion : ✔ A faulty Fibre Channel (FC) cable on dbnode8 was identified as the root cause of the intermittent performance issue. ✔ The issue was completely resolved after replacing the affected FC cable. ✔ Post-replacement monitoring confirmed that no further performance issues were observed. ✔ The log file sync wait event latency remained consistently within the acceptable threshold, indicating healthy storage I/O performance. ✔ This case demonstrates that intermittent FC cable faults can introduce storage path latency and impact Oracle database performance. ✔ Always include end-to-end SAN path validation—including HBAs, FC cables, SAN switches, and storage ports—when troubleshooting Oracle database I/O latency. 🎉 Enjoy the troubleshooting journey!!! 📝 Stay tuned for a detailed blog post on this case !!! |
Thanks for reading this post ! Please comment if you like this post ! Click on FOLLOW to get next blog updates !
