یک RAC سه نود بر روی اوراکل نسخه 12.2 داریم. مدتی بود در وقت های پیک کاری اپلیکیشن، با ویت ایونت gc current block 2-way و ... و با مقدار بالا برخورد میکردم به نحوی که کارکرد اپلیکیشن رو مورد تاثیر خود قرار داده بود. از طرفی تمام موارد مرتبط با GC در کلاستر رو با دقت و وسواس بالا با توجه به آخرین Best Practiceها پیکربندی و بازبینی کرده بودم (به خصوص پارامترهای مرتبط با LMS مانند GCS_SERVER_PROCESSES) و با مانیتورینگ شبکه و سرعت Interconnect هام از سرعت و وضعیت خوب اونها مطمئن بودم همچنین با توجه به مشاهدات محیطی به این نتیجه رسیده بودم که در طول 2 ماه کارکرد اپلیکیشن تنها در انتهای بازه های پیک اپلیکیشن این مشکل دیده میشد پس این موضوع کنجکاوی من رو برای این که بفهمم مشکل کجا بود بیشتر کرد.

تو بررسی هام از طریق Memory Advisor در Enterprise Manager متوجه شدم که در این روزها فضای shared pool به طرز قابل توجهی بالا میره و فضای buffer cache بسیار کوچیک میشه پس با این فرض همه چیز منطقی به نظر میومد. چون با رشد فضای shared pool فضای کافی برای buffer cache نبود.

زمانی که سیستم در وضعیت و پرفورمنس مناسب قرار داشت

 

زمانی که سیستم با ویت های کلاستر زیاد رو به رو میشد و پرفورمنس مناسب نداشت

 

همونطور که می بینید فضای shared pool در برخی مواقع به 110 گیگ هم میرسید و عملا فضایی برای buffer cache باقی نمیذاشت. اولین چیزی که به ذهن میرسه بررسی فضای shared pool ه که چرا این فضا رشد پیدا میکنه؟ باید دلیل رشد رو پیدا میکردم. پس با استفاده کوئری زیر دنبال سرنخ هایی گشتم.

select cr_shared_pool_size, sum_obj_size, sum_sql_size, sum_user_size,
 (sum_obj_size + sum_sql_size+sum_user_size)* 1.3 min_shared_pool
 from (select sum(sharable_mem) sum_obj_size from v$db_object_cache where type<> 'CURSOR'),
 (select sum(sharable_mem) sum_sql_size from v$sqlarea),
 (select sum(250*users_opening) sum_user_size from v$sqlarea),
 (select to_Number(b.ksppstvl) cr_shared_pool_size from x$ksppi a, x$ksppcv b, x$ksppsv c
 where a.indx = b.indx and a.indx = c.indx
 and a.ksppinm ='__shared_pool_size' );

همونطو که می بینید سایز اشغال شده توسط کوئری ها بسیار زیاده پس من به دنبال سرنخ های بیشتر گشتم. شک کردم مشکل میتونه از Library cache باشه چون جایی که statementها چک میشن پس وضعیت اون رو با کوئری زیر چک کردم:

SELECT NAMESPACE, PINS, PINHITS, RELOADS, INVALIDATIONS
FROM V$LIBRARYCACHE
ORDER BY INVALIDATIONS desc;

تعداد بالای INVALIDATION در بخش SQL AREA به من اطمینان داد مشکلی در سمت اپلیکیشن و کوئری ها وجود داره. اگه بخوایم یه مرور سریع داشته باشیم کاری که در Library Cache اتفاق میوفته Parse و ذخیره رشته کوئری ها به جهت کش برای دیتابیس است.

به عنوان یک workaround سریع به ذهنم رسید که مقداری به فضای buffer cache اختصاص بدم چون مطابق مستند اوراکل در حالت ASMM وقتی شما به SGA و PGA مقدار دادید و همچنین به buffer cache و shared pool مقدار میدید اون مقدار رو به عنوان minimum مقدار برای اون بخش در نظر میگیره و امکان رشد رو بهش میده

بخشی از مستند اوراکل مرتبط با ASMM

 

بخشی از مستند اوراکل مرتبط با ASMM

 

پس مقدار 40 گیگ به buffer cache دادم و ایندفعه گذاشتم shared pool به صورت داینامیک و float مقدار بگیره بعد از این تغییر در محیط به مدت 1 ساعت موضوع رو تست کردم. برخلاف تصورم رشد shared pool خیلی زیاد انجام میشد و باعث ایجاد خطاهای ORA-04031: unable to allocate nn bytes of shared memory موقع اجرای کوئری ها شد. نتیجه این تست این شد که فعلا فقط به shared pool مثل گذشته (30 گیگ) مقدار بدم و بذارم به رشد خودش ادامه بده و به buffer cache مقداری ندم تا به صورت float همانند گذشته کار کنه (0) و حتی اگه buffer cache کوچک شد بذارم ویت های کلاستر ادامه داشته باشه تا مشکل رو به صورت ریشه ای بررسی کنم.

نکته: دقت کنید به طور معمول فضای buffer cache در SGA باید بزرگتر از shared pool باشه و افزایش shared pool به 110  گیگ تغییر بزرگی تو سیستم محسوب میشه

نمایی از ویت کلاستر

 

با گرفتن یک downtime فعلا فضای shared pool رو خالی کردم تا بتونم بررسی دقیقتری با استفاده از AWR کنم. کاری که کردم این بود روزهایی که در لود بار ویت کلاستر زیاد داشتیم رو یادداشت کردم و شروع به گرفتن AWR در بازه 1 ساعت ه پیک کاری کردم:

cd $ORACLE_HOME/rdbms/admin
sqlplus / as sysdba
SQL> @awrrpti.sql
Enter html
Enter the number of days (may not be prompted)
Enter the start snap ID
Enter the end snap ID
Enter the report name
Enter.

فکرم حسابی درگیر شده بود نشستم گزارش AWR رو با دقت و وسواس خوندم (حتی تو خواب مرور میکردم) سیستم همیشه Hard Parse زیادی به دلیل نداشتن bind variable داشت (که تا حدودی با قرار دادن پارامتر cursor sharing بر روی force شرایط بهتر شده بود) اما افزایش shared pool موضوع من بود بعد از مرور چندباره AWR متوجه بالا بود مقدار failed parse ها شدم...

12 درصد در 1 ساعت واقعا زیاده... دقت کنید به طور معمول شما اصلا نباید failed parse داشته باشید...

failed parse زیاد می‌تونه موقعیتی ایجاد کنه که اپلیکیشن همواره در تلاش برای پارس کردن SQL باشه. این مساوی ه با parse خیلی زیاد، که اوراکل رو مجبور برای تقاضای shared pool بیشتر میکنه، بالا رفتن failed parse باعث ایجاد لود بالا در shared pool شده و دیتابیس رو مجبور به افزایش فضای shared pool میکنه این رخداد باعث کوچیک شدن فضای buffer cache شده پس دیتابیس باید با بافرهای کمتری برای بلاک های دیتا کار کنه پس در هنگامی که نیاز به تلاش زیاد برای گرفتن buffer cache است زمان بیشتری رو باید منتظر گرفتن مقدار موردنیاز برای لود دیتا در buffer cache بکنه و این تاخیر باعث ایجاد ویت های GC گوناگون در کلاستر میشه

طبق مستند How to Identify Hard Parse Failures Such as Error=923 (Doc ID 1353015.1) از متالینک اوراکل در نسخه 12.2 یک بهینه‌سازی جهت Diagnostic وجود داره که بدون تنظیم کردن رویداد 10035 (مرتبط با نمایش failed parse های سیستم)، به شما یک هشدار زودهنگام در alert.log نمایش می‌دهد. به‌ طور پیش‌فرض، failed parse دستور همراه با warning به ازای هر 100 خطای پارس برای SQL در بازه زمانی 60 دقیقه، ایجاد خواهد شد.

بخشی از مستند 1353015.1

پس با دقت بیشتر به بررسی alertlog ها و به امید دیدن statementهای failed parse شده پرداختم. درسته پیداشون کردم.

--in alertlog instance1
WARNING: too many parse errors, count=154 SQL hash=0x89ebb244
PARSE ERROR: ospid=35841, error=947 for statement:
...

--in alertlog instance2
WARNING: too many parse errors, count=106 SQL hash=0x89ebb244
PARSE ERROR: ospid=27438, error=947 for statement:

--in alertlog instance3
WARNING: too many parse errors, count=2842 SQL hash=0x89ebb244
PARSE ERROR: ospid=42650, error=947 for statement:

نکته: تو این سیستم چون مدیریت سیشن ها توسط اپلیکیشن سرورها و خود اپلیکیشن با مشکل جدی رو به رو هستش سیشن های IDLE بیش از 30 دقیقه توسط پروفایل KILL میشه. همین باعث بالا رفتن حجم alertlog دیتابیس و ندیده شدن warning ها شده بود.

حالا که مشکل رو پیدا کرده بودم باید میدیدم چرا این statementها failed میشن اینطوری بهتون بگم از عمده دلیل های failed parse اشتباهات در موقع Develop سیستم هستش به عنوان مثال در statementهایی که در alertlog گزارش داده شده بود دولوپر به جداول فیلدهایی اضافه کرده بود ولی در insert های قدیمی چون اسامی فیلدها رو نیاورده بود مقادیر ورودی با جدول یکسان نبود و statement به خطای پارس میخورد.

یکی دیگه از موارد عمده failed parse به این صورت ه که Developer اومده select نوشته ولی یه جاهایی اشتباه نوشته مثلا select * from emp رو نوشته selct * form emp

شاید فکر کنید داستان همینجا تموم شد ولی نه...

مشکل رو پیدا کرده بودم ولی statement ای که در alert برای من نشون داده شده بود فقط باعث ایجاد درصد کمی از failed parse سیستم شده بود پس بعد از اصلاح اون تو چند نوبت AWR گرفتم تا درصد اصلاح رو ببینم

همونطور که میبینید به 8 درصد رسیدیم خب پیشرفت خوبی داشتیم ولی بازم کار زیاد داشتیم...

تو بازه های مختلف AWR رو چک کردم و تو برخی بازه ها  failed parse خیلی بیشتر از قبل هم داشتیم...

دوباره به بررسی alertlog پرداختم تا failed parseهای بالای 100 تا رو ببینم

--in alertlog instance1
WARNING: too many parse errors, count=778 SQL hash=0x752a1c21
PARSE ERROR: ospid=3356, error=947 for statement:

--in alertlog instance2
WARNING: too many parse errors, count=1649 SQL hash=0x752a1c21
PARSE ERROR: ospid=28640, error=947 for statement:

همونطور که می بینید فقط یک statement بالای 1600 بار failed شده!!!! این مشکل هم مثل قبل DEVELOPER به جداول فیلد اضافه کرده بود ولی یادش رفته بود اسم فیلدها رو تو insert ها بیاره و مقادیر کم داده بود یه چیزی مثل مثال زیر:

CREATE TABLE EMPLOYEE
(
 ID NUMBER,
 NAME VARCHAR2(1 BYTE),
 FAMILY VARCHAR2(1 BYTE),
 AGE NUMBER
);

INSERT INTO EMPLOYEE VALUES (1, 'TEST', 'TESTFAMILY');

ORA-00947: not enough values

و در نتیجه DEVELOPERهای عزیزی که خطاهای دیتابیس رو raise میکنن تا سیستم به اکسپشن های دیتابیسی نخوره ...

بعد از اصلاح این statement بازم به بررسی AWR سیستم پرداختم تا وضعیت رو بررسی کنم:

وضعیت بهتری نداشتم یقینا failed parse ها بیشتر از اونی بود که warning ها نشون میداد همچنین دیگه warningای در alertlog ایجاد نمیشد. پس طبق مستند 1353015.1 فعالسازی event مرتبط رو در یک بازه 30 دقیقه ای انجام دادم:

ALTER SYSTEM SET EVENTS '10035 trace name context forever, level 1';
--After 30 minutes:
ALTER SYSTEM SET EVENTS '10035 trace name context off';

بعد از دیدن این event فقط حال من رو یک ادمین درک میکرد... حجم بسیار بالای SQLهای مشکل دار بود که داشت میومد...

PARSE ERROR: ospid=40575, error=10980 for statement:
...
PARSE ERROR: ospid=14630, error=932 for statement:
...
PARSE ERROR: ospid=16709, error=936 for statement:
...
PARSE ERROR: ospid=16709, error=1727 for statement:
...

خطاهای ORA-10980 ، ORA-01727 ، ORA-00936 ، ORA-00932 با تعداد زیاد .... فکر کنید تو یه بازه نیم ساعت ه فقط در یک نود 15 هزار خطای failed parse وجود داشت. به ترتیب تو نودهای دیگه هم تقریبا 12 تا 15 هزار failed parse در نیم ساعت گزارش شده بود.

خب دیگه از اینجا به بعد مشخص ه که باید این statementها اصلاح بشن تا سلامت سیستم بازگرده ولی به عنوان یک woraround سریع طبق مستند 1353015.1 من یک hidden parameter تنظیم کردم.

یادتون باشه تعداد بالای sql های failed شده (مشکل دار از لحاظ سینتکس) میتونه منجر به رقابت زیاد بین cpu و library cache بشه و باعث بالا رفتن CPU هم بشه. در بهترین حالت، راه‌حل، بهینه سازی statementهای اپلیکیشن جهت اجرای sql های درست است.
به‌عنوان یک راه‌حل موقت، میشه پارامتر cursor_features_enabled_ را به جهت تسهیل در تأثیر بار منفی failed parse در سیستم مطابق مستند متالینک پیکربندی کرد.

با افزایش 32 تایی مقدار این پارامتر (به طور پیشفرض دارای مقدار 2 است) خطاهای failed parse هر statement در یک جدول $SQLERROR به صورت چک شده درج میشه، تلاشهای زیاد برای پارس کردن statementهای نامعتبر زیاد از نظر syntax یا semantic بعد از پیکربندی این پارامتر باعث تحمیل هزینه failed parse در کل هزینه‌ hard parsing نمیشه.

نکته: تنظیم hidden parameter در اوراکل نیازمند downtime است. پس اگه راه حل موقت و downtime رو نمیخواین به اصلاح statementها بپردازید.

_cursor_features_enabled is not dynamic and requires a restart:

SQL> show parameter _cursor_features_enabled

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
_cursor_features_enabled             integer     32

SQL> alter system set "_cursor_features_enabled" = 34 scope=spfile;

System altered.

و اگه میخواین این موضوع رو در محیط Test تست کنید میتونید از برنامه زیر جهت شبیه سازی استفاده کنید:

BEGIN
 LOOP 
 BEGIN 
 EXECUTE IMMEDIATE 'select count(*) from dual where blah = 5'; 
 EXCEPTION 
 WHEN others THEN NULL; 
 END; 
 END LOOP;
END;
/

نتیجه بعد از set کردن hidden parameter اشاره شده و غیرفعال کردن پارامترهای SPM:

 

در نهایت حتما به حل مسائل این statementها برسید تا performance بهتری داشته باشید.

 

منابع

دریافت Estimate Shared Pool Size

دریافت Shared Pool Management

دریافت Monitoring shared pool usage