Master Yavor from Tryavna

Вчера писах за изявлението на Лари Елисън. Днес вече имаме и видео, от сайта на Sun.

Enjoy 🙂

ctss е нов полезен инструмент, част от клъстерния стек на Oracle от версия 11.2. Той се грижи да няма голяма разлика между часовниците на всички нодове в един клъстер.

Какъв е проблема с часовниците?

За да работи правилно един клъстер, особено в active-avtive режим, между всички нодове постоянно прескачат съобщения „Жив ли си?“ – „Жив съм“. Така при отпадането на един нод, другите знаят, че трябва да поемат неговата работа. Ако някой нод не отговори достатъчно бързо на запитването „Жив ли си?“, другите го обявяват за мъртъв, поемат неговата работа, и за да не стане беля, го изритват от клъстера (за по-сигурно). Процеса на изритване се нарича node eviction и вече съм споменавал за него. Самото изритване на практика представлява възможно най-бърз и брутален рестарт на „губещия“, при който на windows се вижда един приятно син екран. Между другото, до сега се разчиташе на някакво съдействие от изритания нод, за да подейства изритването, но в 11.2 има опит да се използва management процесора, ако има такъв и ако отговаря на стандарта IPMI версия 1.5.

Както и да е. Понякога с тези въпроси кой е жив възниква проблем. Представете си следната ситуация:
1. Даден нод изпраща запитване до някой друг „жив ли си“.
2. 4 милисекунди след това ntpd на същия нод се събужда и сверява часовника, който е изостанал с 2 минути.
3. Още 2 милисекунди по-късно нашият нод решава, че другият не му отговаря вече над 2 минути и го изритва.
Естествено, това е прекалено опростено. Всъщност ntpd се опитва да не прескача по много време (само по 128 ms), но въпреки това понякога го прави. Практиката показва, че такива неща се случват.

Има и други проблеми със стандартните методи за синхронизация на времето. Примерно, когато се опитваме да видим защо дадена заявка е бавна и преглеждаме wait events, може (в случай като горния) да видим, че прочитането на един единствен блок от диска е отнело 2 минути вместо десетина милисекунди. Или обратно – може да излезе отрицателно време. Всичко това се дължи на „подскачането“ на часовника при сверяване.

Oracle Cluster Time Synchronization Service Daemon (octssd)

За това в 11.2 Oracle въвеждат нов процес в clusterware стека, който да отговаря специално за сверяването на часовника. За сега този демон първо се оглежда дали има работещ ntpd. Ако има, влиза в т.нар. observer mode, за да не развали хубавата конфигурация, която е направил системния администратор. (Всъщност имам подозрение, че се опитва да си хортува с ntpd – да му набута опция -x – но това не е описано в документацията).

Ако няма работещ ntpd, octssd влиза в active mode и започва да сверява часовниците на всички нодове. Според документацията, ги сверява спрямо часовника на един „референтен“ нод. На база на някои съобщения в логовете аз мисля, че използва статистически методи: изчислява „средното“ време между всичките и сверява всички часовници с него. От където и да взема времето, сверяването се прави плавно, със забавяне или забързване на часовника на съответния нод, за да се намалят до минимум гореописаните проблеми.

Къде е мотиката?

Проблема е, че ако има твърде голяма разлика между часовниците на нодовете, ctss отказва да се стартира (аналогично би постъпил и ntpd) и в резултат целият clusterware не тръгва. Това в общи линии е добре – това е индикация за реален проблем – но може да бъде доста стряскащо за някой, който не знае за тази особеност. Още повече, че има някои леко объркващи съобщения в alert log-а на клъстеруеъра. За това човек трябва да гледа не само последния ред, а и малко преди него:

[root@ghost ghost]# date
Mon Sep  7 11:06:24 EEST 2009
[root@ghost ghost]# date -s "7 SEP 2008 11:06:40"
Sun Sep  7 11:06:40 EEST 2008
[root@ghost ghost]# /ora_crs/grid/bin/crsctl start crs
CRS-4123: Oracle High Availability Services has been started.
[root@ghost ghost]# tail alertghost.log
2008-09-07 11:07:52.872
[crsd(21173)]CRS-1013:The OCR location in an ASM disk group is inaccessible. Details in /ora_crs/grid/log/ghost/crsd/crsd.log.
2008-09-07 11:07:53.813
[ohasd(20591)]CRS-2765:Resource 'ora.crsd' has failed on server 'ghost'.
2008-09-07 11:07:54.893
[crsd(21187)]CRS-1013:The OCR location in an ASM disk group is inaccessible. Details in /ora_crs/grid/log/ghost/crsd/crsd.log.
2008-09-07 11:07:55.838
[ohasd(20591)]CRS-2765:Resource 'ora.crsd' has failed on server 'ghost'.
2008-09-07 11:07:55.838
[ohasd(20591)]CRS-2771:Maximum restart attempts reached for resource 'ora.crsd'; will not restart.

[root@ghost ghost]# /ora_crs/grid/bin/crsctl check crs
CRS-4638: Oracle High Availability Services is online
CRS-4535: Cannot communicate with Cluster Ready Services
CRS-4529: Cluster Synchronization Services is online
CRS-4533: Event Manager is online
[root@ghost ghost]# /ora_crs/grid/bin/crs_stat -t
CRS-0184: Cannot communicate with the CRS daemon.

Тук съобщението „The OCR location in an ASM disk group is inaccessible“ е малко стряскащо и много подвеждащо. От файла /ora_crs/grid/log/ghost/crsd/crsd.log също изскачат стряскащи и подвеждащи съобщения:

2008-09-07 11:07:54.891: [  OCRASM][3670413808]proprasmo: Error in open/create file in dg [DATA01]
[  OCRASM][3670413808]SLOS : SLOS: cat=7, opn=kgfoAl06, dep=15077, loc=kgfokge
ORA-15077: could not locate ASM instance serving a required diskgroup

2008-09-07 11:07:54.893: [  OCRASM][3670413808]proprasmo: kgfoCheckMount returned [7]
2008-09-07 11:07:54.893: [  OCRASM][3670413808]proprasmo: The ASM instance is down
2008-09-07 11:07:54.893: [  OCRRAW][3670413808]proprioo: Failed to open [+DATA01]. Returned proprasmo() with [26]. Marking location as UNAVAILABLE.
2008-09-07 11:07:54.893: [  OCRRAW][3670413808]proprioo: No OCR/OLR devices are usable
2008-09-07 11:07:54.893: [  OCRASM][3670413808]proprasmcl: asmhandle is NULL
2008-09-07 11:07:54.893: [  OCRRAW][3670413808]proprinit: Could not open raw device
2008-09-07 11:07:54.893: [  OCRASM][3670413808]proprasmcl: asmhandle is NULL
2008-09-07 11:07:54.893: [  OCRAPI][3670413808]a_init:16!: Backend init unsuccessful : [26]
2008-09-07 11:07:54.894: [  CRSOCR][3670413808] OCR context init failure.  Error: PROC-26: Error while accessing the physical storage ASM error [SLOS: cat=7, opn=kgfoAl06, dep=15077, loc=kgfokge
ORA-15077: could not locate ASM instance serving a required diskgroup
] [7]
2008-09-07 11:07:54.894: [    CRSD][3670413808][PANIC] CRSD exiting: Could not init OCR, code: 26
2008-09-07 11:07:54.894: [    CRSD][3670413808] Done.

Нищо му няма на OCR файла, нито има проблем с пътя до него. Проблема е, че върнах часовника с една година назад и ctss отказва да отлепи . Това си го пише в /ora_crs/grid/log/ghost/ctssd/octssd.log:

2008-09-07 11:07:34.674: [  clsdmt][1160481088]Creating PID [21073] file for home /ora_crs/grid host ghost bin ctss to /ora_crs/grid/ctss/init/
2008-09-07 11:07:34.674: [  clsdmt][1160481088]Writing PID [21073] to the file [/ora_crs/grid/ctss/init/ghost.pid]
2008-09-07 11:07:34.674: [    CTSS][1149991232]ctsselect_mmg8: Host [spectre] Node num [1] is the master
2008-09-07 11:07:34.675: [    CTSS][1149991232]ctsselect_sm2: Node [1] is the CTSS master
2008-09-07 11:07:34.675: [    CTSS][1149991232]ctssslave_meh1: Master private node name [spectre]
2008-09-07 11:07:34.675: [    CTSS][1149991232]ctssslave_msh: Connect String is (ADDRESS=(PROTOCOL=tcp)(HOST=spectre)(PORT=16569))
2008-09-07 11:07:34.676: [    CTSS][1149991232]ctssslave_msh: Forming connection with CTSS master node [1]
2008-09-07 11:07:34.677: [    CTSS][1149991232]ctssslave_msh: Successfully connected to master [1]
2008-09-07 11:07:34.677: [    CTSS][1149991232]ctssslave_swm: The magnitude [31536002073184 usec] of the offset [-31536002073184 usec] is larger than [86400000000 usec] sec which is the CTSS limit.
2008-09-07 11:07:34.677: [    CTSS][1149991232]ctsselect_mmg9_3: Failed in clsctsselect_select_mode [12]: Time offset is too much to be corrected
2008-09-07 11:07:35.610: [    CTSS][1160481088]ctss_checkcb: clsdm requested check alive. Returns [40000050]
2008-09-07 11:07:35.610: [    CTSS][3009136672]ctss_init: Spawn completed. Waiting for threads to join
2008-09-07 11:07:35.610: [    CTSS][1149991232]ctsselect_mmg: CTSS daemon exiting [12].
2008-09-07 11:07:35.611: [    CTSS][1149991232]CTSS daemon aborting

Пише го и в alert log-а на клъстера, но е няколко десетки реда преди края на файла:

2008-09-07 11:07:22.547
[ctssd(21042)]CRS-2401:The Cluster Time Synchronization Service started on host ghost.
2008-09-07 11:07:34.675
[ctssd(21073)]CRS-2407:The new Cluster Time Synchronization Service reference node is host spectre.
2008-09-07 11:07:34.677
[ctssd(21073)]CRS-2404:The Cluster Time Synchronization Service detects that the local time is significantly different from the mean cluster time. Details in /ora_crs/grid/log/ghost/ctssd/octssd.log.

Оправията, естествено, е да се свери долу-горе времето, за да може ctss да запали.

[root@ghost ghost]# date -s "7 SEP 2009 11:26:40"
Mon Sep  7 11:26:40 EEST 2009
[root@ghost ghost]# /ora_crs/grid/bin/crsctl stop crs
CRS-2796: The command may not proceed when Cluster Ready Services is not running
CRS-4687: Shutdown command has completed with error(s).
CRS-4000: Command Stop failed, or completed with errors.

[root@ghost ghost]# /ora_crs/grid/bin/crsctl stop crs -f
CRS-2791: Starting shutdown of Oracle High Availability Services-managed resources on 'ghost'
. . .
CRS-2793: Shutdown of Oracle High Availability Services-managed resources on 'ghost' has completed
CRS-4133: Oracle High Availability Services has been stopped.

[root@ghost ghost]# /ora_crs/grid/bin/crsctl start crs
CRS-4123: Oracle High Availability Services has been started.

[root@ghost ghost]# tail -n 10 alertghost.log
2009-09-07 11:29:48.718
[ctssd(25311)]CRS-2408:The clock on host ghost has been updated by the Cluster Time Synchronization Service to be synchronous with the mean cluster time.
2009-09-07 11:29:49.653
[ctssd(25311)]CRS-2401:The Cluster Time Synchronization Service started on host ghost.
[client(25508)]CRS-10001:ACFS-9327: Verifying ADVM/ACFS devices.
[client(25527)]CRS-10001:ACFS-9322: done.
2009-09-07 11:30:00.087
[crsd(25726)]CRS-1012:The OCR service started on node ghost.
2009-09-07 11:30:01.503
[crsd(25726)]CRS-1201:CRSD started on node ghost.

Къде е по-дебелата мотика?

Същият този проблем възниква със страшна сила по време на инсталацията на Grid infrastructure. В самият край на инсталацията, при стартирането на root.sh на последния нод, octssd гръмва и прекратява изпълнението на скрипта. В резултат работата остава недовършена – най-малкото, което забелязах е, че на този нод не му се случва VIP. Което е особено тъжно предвид факта, че в 11.2 няма vipca и VIP се прави ръчно, чрез srvctl.

Така че преди инсталация (или ъпгрейд) гледайте часовниците на всичките нодове да са горе-долу в синхрон. Надявам се, че от следващата версия тази проверка ще се прави и от самия инсталатор.

Една от малките, но удобни благинки в 11.1 (release one!) е новият синтаксис на ALTER SYSTEM KILL SESSION. Освен стандартните SID и SERIAL, вече има трети, опционален параметър, в който може да се зададе instance id. Това позволява да се прекъсват сесии на „друг“ instance.

Според документацията нещата стоят така:

KILL SESSION Clause

The KILL SESSION clause lets you mark a session as terminated, roll back ongoing transactions, release all session locks, and partially recover session resources. To use this clause, your instance must have the database open. Your session and the session to be terminated must be on the same instance unless you specify integer3.You must identify the session with the following values from the V$SESSION view:

– For integer1, specify the value of the SID column.

– For integer2, specify the value of the SERIAL# column.

– For the optional integer3, specify the ID of the instance where the target session to be killed exists. You can find the instance ID by querying the GV$ tables.

Тук, обаче, не е цялата истина. Ето какво се случва ако следваш документацията:

SQL> select instance_number from v$instance;
 
INSTANCE_NUMBER
---------------
              1
 
SQL> select inst_id, sid, serial#
  2    from gv$session
  3   where username = 'YAVOR'
  4     and program not like '%PZ99%';
 
   INST_ID        SID    SERIAL#
---------- ---------- ----------
         1         12      29935
         1        587       2564
         1       1153       6987
         1       1715       1807
         2        583        494

SQL> alter system kill session '583, 494, 2';
 
alter system kill session '583, 494, 2'

ORA-00026: missing or invalid session ID

Изречението „You can find the instance ID by querying the GV$ tables“ не носи много полезна информация. Тук някой може да си помисли, че описанието на грешка ORA-00026 в същата тази документация ще е полезно. Ето колко е полезно:

ORA-00026: missing or invalid session ID
Cause: Missing or invalid session ID string for ALTER SYSTEM KILL SESSION.
Action: Retry with a valid session ID.

Човек веднага се сеща какъв е проблема, нали 🙂

Чак ме е яд как не ми блесна веднага: следвайки синтаксиса от първите два параметъра (SID и Serial#), съвсем логично е, че третият параметър се задава с @ (кльомба/маймунка). Няма нужда това да се пише в документацията – то е толкова естествено…

SQL> alter system kill session '583,494,@2';
 
alter system kill session '583,494,@2'
 
ORA-00031: session marked for kill
 
SQL> select inst_id, sid, serial#
  2    from gv$session
  3   where username = 'YAVOR'
  4     and program not like '%PZ99%';
 
   INST_ID        SID    SERIAL#
---------- ---------- ----------
         1         12      29935
         1        587       2564
         1       1153       6987
         1       1715       1807

P.S.: И в 11.2 е така