Mercredi 27 mars 2013 3 27 /03 /Mars /2013 08:42

 

Last weekend, I found the origin of the SVM bug using the mdb tool. Good reading !! 

 

After restarting the server, I wanted to mount a filesystem (metaset object), but the following command was not responding...

 

# metaset
^Cmetaset: Interrupt

 

Very strange... I tested another SVM command.

 

# metastat
^Cmetastat: Interrupt

 

Hmm "bizarre"... All SVM commands were blocked. Is there a blocked SVM process ?

 

# pgrep -fl meta
12140 /usr/sbin/metasync -r

 

Yes of course !? But this process is only used to resync a meta element. Is there a problem with a device ? My first action : I checked the system logs looking for disk errors. No errors were reported in the system logs.

 

What does the metasync process do ? I check the activity of this process

 

# truss -aefl -p 12140
12140/1:        psargs: /usr/sbin/metasync -r
^C

 

Nothing... A more thorough analysis is essential to understand this problem. I use mdb to check a stack of this thread.

 

# mdb -k
Loading modules: [ unix genunix dtrace specfs ufs sd mpt pcisch sgsbbc ssd fcp fctl md ip hook neti qlc sgenv sctp arp usba lofs zfs cpc fcip random crypto logindmux ptm nfs ipc ]

> 0t12140::pid2proc
60053be24f0

> 60053be24f0::walk thread |::findstack -v
stack pointer for thread 30160427920: 2a100e92d21
[ 000002a100e92d21 sema_p+0x138() ]
  000002a100e92dd1 biowait+0x6c(600520ca500, 0, 18b7c00, 300b17ae000, 8, 600520ca500)
  000002a100e92e81 default_physio+0x388(12f650c, 200, 0, 600520ca540, 12e6c38, 600520ca538)
  000002a100e92fb1 scsi_uscsi_handle_cmd+0x1b8(20000000b0, 1, 60053d18238, 12f650c, 600520ca500, 60053fed7c0)
  000002a100e930a1 sd_send_scsi_cmd+0x114(20000000b0, 1964c00, 60053fed7c0, 1, 3009f2ca6c0, 2a100e93a30)
  000002a100e93161 sd_send_scsi_RDWR+0x2bc(600500ccf80, 10000, 14, 2a100e93a1c, 2a100e93a70, 1)
  000002a100e93281 sd_use_efi+0x90(3009f2ca6c0, 1, 0, 6a945a3b, 130a3fc, 3041df72000)
  000002a100e93351 sd_validate_geometry+0xc8(3009f2ca6c0, 1, 60, 1, 7, ea000050)
  000002a100e93411 sd_ready_and_valid+0x2d4(3009f2ca6c0, ea, ea000050, 600500ccf80, 30, 0)
  000002a100e93521 sdopen+0x248(8, 3009f2ca6c0, 3, 196c6d8, 3009f2ca7a0, 0)
  000002a100e935d1 PxOpenNativeDev+0x148(600515ab510, 3, 701ae328, 4, 60050003e00, 3011bb3a7a0)
  000002a100e936e1 PxSolUpdateSize+0x78(600515ab510, 60053e523d0, 60053e525f0, 20, ffffffff, 3)
  000002a100e937b1 PowerPlatformBottomDispatch+0x150(600515ab510, 60053e523d0, 0, 0, 60050555558, 20000000b0)
  000002a100e939d1 PowerBottomDispatch+0xa0(600515ab510, 60053e523d0, 0, 0, 600547cd74c, 600515ab250)
  000002a100e93aa1 PowerBottomDispatchPirp+0x88(600515ab250, 60053e523d0, 9, 60053e523d0, 600515a5718, 600515ab510)
  000002a100e93b71 PowerDispatch+0x3a4(600515a9470, 60053e523d0, 60053e52630, 0, 600547cd718, 600515ab250)
  000002a100e93c81 GpxDispatch+0x68(600515a9378, 60053e523d0, 600547cd728, 60053e525b0, 600515a57e8, 0)
  000002a100e93d61 PowerDispatch+0x264(600515a9378, 60053e523d0, 60053e52610, 0, 0, 600515ab250)
  000002a100e93e71 GpxDispatch+0x68(600515a9280, 60053e523d0, ffffffffffffffff, 7bf12e987bf22408, 600515a5780, 0)
  000002a100e93f51 PowerDispatch+0x264(600515a9280, 60053e523d0, 60053e525f0, 0, 2a100e94531, 600515ab250)
  000002a100e94061 GpxDispatch+0x68(600515a9188, 60053e523d0, 20f, 0, 60050555558, 0)
  000002a100e94141 PowerDispatch+0x264(600515a9188, 60053e523d0, 60053e525d0, 0, 600547cd74c, 600515ab250)
  000002a100e94251 GpxDispatch+0x68(600515a9090, 60053e523d0, 9, 60053e523d0, 600515a5718, 0)
  000002a100e94331 PowerDispatch+0x264(600515a9090, 60053e523d0, 60053e525b0, 0, 600547cd718, 600515ab250)
  000002a100e94441 PxUpdateSize+0x80(600515a9090, 0, 600547cd728, 60053e525b0, 600547cd728, 60053e523d0)
  000002a100e94531 power_open+0x5c8(2a100e94f48, 40000003, 2, 60050003e00, 600515ab250, 600515ab510)
  000002a100e94691 spec_open+0x4f8(2a100e950b8, 224, 60050003e00, a01, 60053b3f2d0, 0)
  000002a100e94751 fop_open+0x78(2a100e950b8, 2, 60050003e00, 40000003, 6005483d900, 6005483d900)
  000002a100e94801 dev_lopen+0x34(2a100e95170, 3, 4, 60050003e00, ffffffff, ffffffffffffffff)
  000002a100e948c1 md_layered_open+0x120(13, 2a100e95258, 1, 300ad44b084, 20000000b0, 60050003e00)
  000002a100e94981 stripe_open_all _devs+0x188(1a, 1, 0, 0, 0, 65)
  000002a100e94a61 stripe_open+0xa0(65, 3, 4, 60050135f68, 600500ede00, 1)
  000002a100e94b11 md_layered_open+0xb8(0, 2a100e954b0, 1, 60050135f68, 65, 60050003e00)
  000002a100e94bd1 mirror_open_all _devs+0x240(1, 60050135770, 2a100e958c0, 300ad585070, 64, 1)
  000002a100e94cc1 mirror_internal_open+0xf0(600501357a0, 3, 4, 0, 2a100e958c0, 0)
  000002a100e94d71 mirror_resync_unit+0x74(60053d0d018, 60053d0d000, 60050135770, 2a100e958c0, 0, 1)
  000002a100e94e31 mirror_admin_ioctl+0x1f8(e, ffbffb00, 102003, 2a100e958c0, 54, 102003)
  000002a100e94f41 md_admin_ioctl+0x130(19c4c00, 19, ffbffb00, 102003, 2a100e958c0, 5615)
  000002a100e95011 mdioctl+0xf4(550003ffff, 5615, ffbffb00, 102003, 60053b97100, 1f)
  000002a100e950e1 fop_ioctl+0x20(600548dd840, 5615, ffbffb00, 102003, 60053b97100, 1288f38)
  000002a100e95191 ioctl+0x184(0, 600501e7778, ffbffb00, fffffff8, 0, 5615)
  000002a100e952e1 syscall_trap32+0xcc(0, 5615, ffbffb00, fffffffffffffff8, 0, ffbffb51)

 

Really interesting, the kthead is suspended by a scsi operation (The function biowait suspends processes pending completion of block I/O operations). Which is the device used ?

 

> 600520ca500::print -t buf_t
{
    int b_flags = 0x2200061
    struct buf *b_forw = 0
    struct buf *b_back = 0
    struct buf *av_forw = 0
    struct buf *av_back = 0
    o_dev_t b_dev = 0
    size_t b_bcount = 0x200
    union  b_un = {
        caddr_t b_addr = 0x303666e1480
        struct fs *b_fs = 0x303666e1480
        struct cg *b_cg = 0x303666e1480
        struct dinode *b_dino = 0x303666e1480
        daddr32_t *b_daddr = 0x303666e1480
    }
    lldaddr_t _b_blkno = {
        longlong_t _f = 0
        struct  _p = {
            int32_t _u = 0
            int32_t _l = 0
        }
    }
    char b_obs1 = '\0'
    size_t b_resid = 0
    clock_t b_start = 0
    struct proc *b_proc = 0
    struct page *b_pages = 0
    clock_t b_obs2 = 0
    size_t b_bufsize = 0
    int (*)() b_iodone = 0
    struct vnode *b_vp = 0
    struct buf *b_chain = 0
    int b_obs3 = 0
    int b_error = 0                  
    void *b_private = 0x300edf4b000
    dev_t b_edev = 0x20000000b0
    ksema_t b_sem = {
        void *[2] _opaque = [ 0, 0 ]
    }
    ksema_t b_io = {
        void *[2] _opaque = [ 0x30160427920, 0 ]
    }
    struct buf *b_list = 0
    struct page **b_shadow = 0x60053df97c0
    void *b_dip = 0x6005013d6d0
    struct vnode *b_file = 0
    offset_t b_offset = 0xffffffffffffffff
}

 

The macro devt enables us to obtain his minor and major numbers

 

> 0x20000000b0::devt
     MAJOR       MINOR
        32         176

 

With the numbers, it's easy to find the name of device (There is a lot of differents methods to obtain the device). For exemple :

 

# cd /devices
# ls -Rl > /tmp/bruno
# view /tmp/bruno

[...]
/ssm@0,0/pci@18,600000/pci@1/scsi@2
[...]
brw-r-----   1 root     sys       32, 176 Mar 23 18:46 sd@9,0:a
[...] 

# grep "/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9" /etc/path_to_inst
"/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0" 22 "sd"

# ls -l /dev/dsk | grep "/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9"
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s0 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:a
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s1 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:b
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s2 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:c
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s3 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:d
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s4 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:e
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s5 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:f
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s6 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:g
lrwxrwxrwx  1 root  root  57 Aug 22 2007 c2t9d0s7 -> ../../devices/ssm@0,0/pci@18,600000/pci@1/scsi@2/sd@9,0:h

 

The unix device is c2t9d0. Impossible to obtain information on this device (format, prtvtoc, ... do not respond). If your production system is correctly configured, Explorer runs every week. This is the moment to use it.

 

# cd /opt/SUNWexplo/output/explorer.84549349.server-2013.03.16.23.05/disks
# grep c2t9d0 diskinfo
c2t9d0      SEAGATE    ST314655LSUN146G     0491 0719S16ZB2 primary

 

With the type of device determined, all we have to do is open a ticket with support and change it.

 

In conclusion, the breakdown of the device not having been brutal, a ioctl has remained suspended. As a result all SVM commands remained suspended. Using mdb, it was easy to diagnose the problem and solve it quickly.

 

Par gloumps - Publié dans : kernel
Ecrire un commentaire - Voir les 0 commentaires

Samedi 23 février 2013 6 23 /02 /Fév /2013 21:37

 

Petite observation lors d’une recette cluster d’un Oracle RAC 11gR2 sur Solaris 10 Sparc. Pendant le test suivant « perte d’une baie SAN », nous avons observé un petit problème lors de la resynchronisation des diskgroups ASM utilisant des volumes sous ACFS. Nous nous attendions à utiliser la fonctionnalité fastresync et pourtant…

 

Observons tout d’abord le contexte initial : « perte d'une baie SAN sur les deux nodes du clusters Oracle RAC ».

 

Perte de la baie sur les deux nodes du cluster RAC (observation système).

 

Feb 12 18:08:55 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(6)::GPN_ID for D_ID=150300 failed
Feb 12 18:08:55 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(6)::N_x Port with D_ID=150300, PWWN=5000097408231998 disappeared from fabric
Feb 12 18:09:52 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(5)::GPN_ID for D_ID=b0300 failed
Feb 12 18:09:52 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(5)::N_x Port with D_ID=b0300, PWWN=50000974082319a4 disappeared from fabric
[…]

 

Feb 12 18:08:55 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(5)::GPN_ID for D_ID=150300 failed
Feb 12 18:08:55 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(5)::N_x Port with D_ID=150300, PWWN=5000097408231998 disappeared from fabric
Feb 12 18:09:52 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(6)::GPN_ID for D_ID=b0300 failed
Feb 12 18:09:52 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(6)::N_x Port with D_ID=b0300, PWWN=50000974082319a4 disappeared from fabric
[…]

 

 

Confirmation des  « path dead » sous powerpath (observation multiptah).

 

rac01 # /etc/powermt display
Symmetrix logical device count=30
CLARiiON logical device count=0
Hitachi logical device count=0
Invista logical device count=0
HP xp logical device count=0
Ess logical device count=0
HP HSx logical device count=0

==============================================================================

----- Host Bus Adapters ---------  ------ I/O Paths -----  ------ Stats ------
###  HW Path                       Summary   Total   Dead  IO/Sec Q-IOs Errors

==============================================================================
3077 pci@11,700000/SUNW,qlc@0/fp@0,0 degraded    30     14      -     0     16
3078 pci@1,700000/SUNW,qlc@0/fp@0,0  degraded    30     14      -     0     20

 

rac02 # /etc/powermt display
Symmetrix logical device count=30
CLARiiON logical device count=0
Hitachi logical device count=0
Invista logical device count=0
HP xp logical device count=0
Ess logical device count=0
HP HSx logical device count=0

==============================================================================

----- Host Bus Adapters ---------  ------ I/O Paths -----  ------ Stats ------
###  HW Path                       Summary   Total   Dead  IO/Sec Q-IOs Errors

==============================================================================
3077 pci@1,700000/SUNW,qlc@0/fp@0,0  degraded    30     14      -     0     17
3078 pci@11,700000/SUNW,qlc@0/fp@0,0 degraded    30     14      -     0     17

 

 

Etat des diskgroups ASM (observation couche ASM).

 

$ asmcmd lsdsk -pk
 Name           Failgroup     … Mount_Stat … Mode_Stat State  Path
 DATA_DG1_0000  DATA_DG1_FG1  … MISSING    …   OFFLINE NORMAL 
 DATA_DG1_0001  DATA_DG1_FG1  … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0002   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0009   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 SYSTEMDG_0000  SYSTEMDG_0000 … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0000   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0001   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0008   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 DUMP_DG_0003   DUMP_DG_FG1   … MISSING    …   OFFLINE NORMAL 
 REDO_DG1_0000  REDO_DG1_FG1  … MISSING    …   OFFLINE NORMAL 
 FLASH_DG1_0000 FLASH_DG1_FG1 … MISSING    …   OFFLINE NORMAL 
 DATA_DG1_0002  DATA_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 DATA_DG1_0003  DATA_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0004   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0005   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0006   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0007   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0010   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0011   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 FLASH_DG1_0001 FLASH_DG1_FG2 … CACHED     …   ONLINE  NORMAL  …
 REDO_DG1_0001  REDO_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 SYSTEMDG_0004  SYSTEMDG_0004 … CACHED     …   ONLINE  NORMAL  …
 SYSTEMDG_0001  SYSTEMDG_000  … CACHED        ONLINE  NORMAL  …

 

 

La perte de la baie est confirmée par les différentes couches (serveurs, multipath, lvm). Le cluster RAC lui fonctionne correctement (un peu normal). Le test est concluant, passons maintenant à la « redécouverte » de la baie et la resynchronisation (fastresync) des diskgroups ASM.

 

Baie online sur les deux nodes du cluster RAC (observation système).

 

Feb 12 18:23:16 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(6)::N_x Port with D_ID=150300, PWWN=5000097408231998 reappeared in fabric
Feb 12 18:23:34 rac01 fctl: [ID 517869 kern.warning] WARNING: fp(5)::N_x Port with D_ID=b0300, PWWN=50000974082319a4 reappeared in fabric
[…]

 

Feb 12 18:23:16 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(5)::N_x Port with D_ID=150300, PWWN=5000097408231998 reappeared in fabric
Feb 12 18:23:34 rac02 fctl: [ID 517869 kern.warning] WARNING: fp(6)::N_x Port with D_ID=b0300, PWWN=50000974082319a4 reappeared in fabric
[…]

 

 

Confirmation des  « path dead » sous powerpath (observation multiptah)

 

rac01 # /etc/powermt display    
Symmetrix logical device count=30
CLARiiON logical device count=0
Hitachi logical device count=0
Invista logical device count=0
HP xp logical device count=0
Ess logical device count=0
HP HSx logical device count=0

==============================================================================

----- Host Bus Adapters ---------  ------ I/O Paths -----  ------ Stats ------
###  HW Path                       Summary   Total   Dead  IO/Sec Q-IOs Errors

==============================================================================
3077 pci@11,700000/SUNW,qlc@0/fp@0,0 optimal     30     0      -     0     16
3078 pci@1,700000/SUNW,qlc@0/fp@0,0  optimal     30     0      -     0     20

 

rac02 # /etc/powermt display    
Symmetrix logical device count=30
CLARiiON logical device count=0
Hitachi logical device count=0
Invista logical device count=0
HP xp logical device count=0
Ess logical device count=0
HP HSx logical device count=0

==============================================================================

----- Host Bus Adapters ---------  ------ I/O Paths -----  ------ Stats ------
###  HW Path                       Summary   Total   Dead  IO/Sec Q-IOs Errors

==============================================================================
3077 pci@1,700000/SUNW,qlc@0/fp@0,0  optimal     30     0      -     0     17
3078 pci@11,700000/SUNW,qlc@0/fp@0,0 optimal     30     0      -     0     17

 

 

La baie est de nouveau visible sur le serveur. Il est donc possible de relancer la resynchronisation des diskgroups ASM.

 

$  sqlplus / as sysasm

SQL*Plus: Release 11.2.0.3.0 Production on Tue Feb 12 18:23:36 2013
Copyright (c) 1982, 2011, Oracle.  All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options

SQL> alter diskgroup data_dg1 online all;
Diskgroup altered.
SQL> alter diskgroup systemdg online all;
Diskgroup altered.
SQL> alter diskgroup redo_dg1 online all;
Diskgroup altered.
SQL> alter diskgroup flash_dg1 online all;
Diskgroup altered.
SQL> alter diskgroup dump_dg online all;
Diskgroup altered.

SQL> set lines 120
SQL> select * from v$asm_operation;

GROUP_NUMBER OPERA STAT POWER ACTUAL SOFAR EST_WORK EST_RATE EST_MINUTES
------------ ----- ---- ----- ------ ----- -------- -------- -----------
ERROR_CODE
--------------------------------------------
           2 ONLIN RUN      1      0     0        0        0           0

 

 

La resynchronisation semble être terminée et pourtant.

 

$ asmcmd lsdsk -pk
 Name           Failgroup     … Mount_Stat … Mode_Stat State  Path
 DATA_DG1_0000  DATA_DG1_FG1  … CACHED     …   ONLINE  NORMAL 
 DATA_DG1_0001  DATA_DG1_FG1  … CACHED     …   ONLINE  NORMAL 
 DUMP_DG_0002   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0009   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 SYSTEMDG_0000  SYSTEMDG_0000 … CACHED     …   ONLINE  NORMAL 
 DUMP_DG_0000   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0001   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0008   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0003   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 REDO_DG1_0000  REDO_DG1_FG1  … CACHED     …   ONLINE  NORMAL 
 FLASH_DG1_0000 FLASH_DG1_FG1 … CACHED     …   ONLINE  NORMAL 
 DATA_DG1_0002  DATA_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 DATA_DG1_0003  DATA_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0004   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0005   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0006   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0007   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0010   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 DUMP_DG_0011   DUMP_DG_FG2   … CACHED     …   ONLINE  NORMAL  …
 FLASH_DG1_0001 FLASH_DG1_FG2 … CACHED     …   ONLINE  NORMAL  …
 REDO_DG1_0001  REDO_DG1_FG2  … CACHED     …   ONLINE  NORMAL  …
 SYSTEMDG_0004  SYSTEMDG_0004 … CACHED     …   ONLINE  NORMAL  …
 SYSTEMDG_0001  SYSTEMDG_000  … CACHED        ONLINE  NORMAL  … 

 

 

Bizarrement le diskgroup ASM dump_dg est encore en cours de synchronisation !? Que se passe-t-il ? Vu qu'il s'agit d'une recette, il n'y a eu aucune activité utilisateurs, ce qui implique aucune modification des données. La resynchronisation entre les deux baies doit être immédiate avec le fasresync. Fonctionne-t-il correctement ?

 

Regardons ce qui se passe dans les logs de l’ASM.

 

$ cd /oracle/base/diag/asm/+asm/+ASM1/trace
$ tail -f alert_+ASM1.log
Tue Feb 12 18:38:55 2013
NOTE: successfully read ACD block gn=2 blk=10752 via retry read
Errors in file /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc:
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=2 blk=10752 via retry read
Errors in file /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc:
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=2 blk=10752 via retry read
Errors in file /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc:
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=2 blk=10752 via retry read
Errors in file /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc:
ORA-15062: ASM disk is globally closed
[…]

 

$ cat /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc
Trace file /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_lgwr_3524.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options
ORACLE_HOME = /oracle/product/11.2.0/grid
System name:    SunOS
Node name:      rac01
Release:        5.10
Version:        Generic_147440-26
Machine:        sun4u
Instance name: +ASM1
Redo thread mounted by this instance: 0 <none>
Oracle process number: 15
Unix process pid: 3524, image: oracle@rac01 (LGWR)

*** 2013-02-12 18:10:12.384
*** SESSION ID:(931.1) 2013-02-12 18:10:12.385
*** CLIENT ID:() 2013-02-12 18:10:12.385
*** SERVICE NAME:() 2013-02-12 18:10:12.385
*** MODULE NAME:() 2013-02-12 18:10:12.385
*** ACTION NAME:() 2013-02-12 18:10:12.385
[…]
*** 2013-02-12 18:10:20.264
NOTE: successfully read ACD block gn=1 blk=10752 via retry read
ORA-15062: ASM disk is globally closed
*** 2013-02-12 18:11:11.444
NOTE: successfully read ACD block gn=1 blk=10752 via retry read
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=2 blk=10752 via retry read
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=4 blk=10752 via retry read
ORA-15062: ASM disk is globally closed
NOTE: successfully read ACD block gn=5 blk=0 via retry read
ORA-15062: ASM disk is globally closed
[…]

 

D'après les logs Oracle, il semble toujours y avoir des opérations ASM. Vérifions les propriétés de ce diskgroup ASM, peut-être y-a-t-il des différences.

 

$ asmcmd
ASMCMD> lsattr -l -G dump_dg
Name                     Value      
access_control.enabled   FALSE      
access_control.umask     066        
au_size                  1048576    
cell.smart_scan_capable  FALSE      
compatible.advm          11.2.0.0.0 
compatible.asm           11.2.0.0.0 
compatible.rdbms         11.2.0.0.0 
disk_repair_time         24h        
sector_size              512

 

 

En la comparant à un autre diskgroup ASM, il n’y a aucune différence. La seule différence est l’utilisation du volume en ACFS. Cherchons différemment...

 

Lancement d’un débat entre les DBA Oracle et moi : pourquoi le diskgroup se synchronise toujours au bout de 20 minutes ?

  • Soit le diskgroup ASM n’utilise pas la fonctionnalité fastresync (si ACFS) ?
  • Soit un bug ASM – ACFS ?
  • Y-a-t-il encore des I/O ?

 

On va mettre tout le monde d’accord avec Dtrace ! Un petit on-liners Dtrace pour trouver le pid effectuant les demandes d’écriture.

 

# dtrace –n 'syscall::write:entry /execname == “oracle”/ \
{ @[pid] = count(); }’

^C
[…]
   3572       1080

 

Effectuons un petit oradebug sur ce PID

 

$ sqlplus / as sysasm

SQL*Plus: Release 11.2.0.3.0 Production on Tue Feb 12 18:23:36 2013
Copyright (c) 1982, 2011, Oracle.  All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Real Application Clusters and Automatic Storage Management options

SQL> oradebug setospid 3572
Oracle pid: 27, Unix process pid: 3572, image: oracle@rac01 (ASMB)
SQL> oradebug unlimit
Statement processed.
SQL> oradebug EVENT 10046 TRACE NAME CONTEXT FOREVER, LEVEL 12
Statement processed.
SQL> oradebug tracefile_name
/oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_asmb_3572.trc
SQL> ! tail -f /oracle/base/diag/asm/+asm/+ASM1/trace/+ASM1_asmb_3572.trc
WAIT #0: nam='ASM file metadata operation' ela= 62 msgop=4 locn=0 p3=0 obj#=-1 tim=443471434898
WAIT #0: nam='ASM file metadata operation' ela= 61 msgop=4 locn=0 p3=0 obj#=-1 tim=443471435027
WAIT #0: nam='ASM file metadata operation' ela= 109 msgop=4 locn=0 p3=0 obj#=-1 tim=443471435205
WAIT #0: nam='ASM file metadata operation' ela= 64 msgop=4 locn=0 p3=0 obj#=-1 tim=443471435338
WAIT #0: nam='ASM background timer' ela= 4175 p1=0 p2=0 p3=0 obj#=-1 tim=443471439572
WAIT #0: nam='ASM file metadata operation' ela= 1 msgop=0 locn=3 p3=0 obj#=-1 tim=443471439636
WAIT #0: nam='ASM file metadata operation' ela= 64 msgop=4 locn=0 p3=0 obj#=-1 tim=443471439751
WAIT #0: nam='ASM file metadata operation' ela= 61 msgop=4 locn=0 p3=0 obj#=-1 tim=443471439967
WAIT #0: nam='ASM file metadata operation' ela= 59 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440102
WAIT #0: nam='ASM file metadata operation' ela= 62 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440231
WAIT #0: nam='ASM background timer' ela= 81 p1=0 p2=0 p3=0 obj#=-1 tim=443471440388
WAIT #0: nam='ASM file metadata operation' ela= 1 msgop=0 locn=3 p3=0 obj#=-1 tim=443471440444
WAIT #0: nam='ASM file metadata operation' ela= 63 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440552
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440681
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440801
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471440937
WAIT #0: nam='ASM background timer' ela= 74 p1=0 p2=0 p3=0 obj#=-1 tim=443471441070
WAIT #0: nam='ASM file metadata operation' ela= 0 msgop=0 locn=3 p3=0 obj#=-1 tim=443471441119
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471441223
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471441347
WAIT #0: nam='ASM file metadata operation' ela= 60 msgop=4 locn=0 p3=0 obj#=-1 tim=443471441472
WAIT #0: nam='ASM file metadata operation' ela= 76 msgop=4 locn=0 p3=0 obj#=-1 tim=443471441614
[…]

SQL> oradebug EVENT 10046 TRACE NAME CONTEXT OFF
Statement processed.

 

 

Nouvelle discussion : il s’agit d’opérations uniquement sur les metadas (synchronisation avec « fastresync »). Alors pourquoi le statut dans ASM est toujours en « SYNCING ». Il n’y a eu aucune mise jours pendant le test !!

 

$ asmcmd lsdsk –pk | grep SYNCING 
 DUMP_DG_0002   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0009   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0000   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0001   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0008   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 
 DUMP_DG_0003   DUMP_DG_FG1   … CACHED     …   SYNCING NORMAL 

 

 

Nouvelle discussion : y-a-t-il vraiment des IO ? N'y a-t-il pas simplement un problème d'affichage du résultat de la commande ? Pour les DBA non, pour moi si. Vérifions.

 

$ asmcmd
ASMCMD> iostat --io -G dump_dg 5
Group_Name  Dsk_Name      Reads  Writes 
DUMP_DG     DUMP_DG_0000  456    67329  
DUMP_DG     DUMP_DG_0001  223    67612  
DUMP_DG     DUMP_DG_0002  223    68516  
DUMP_DG     DUMP_DG_0003  223    66326  
DUMP_DG     DUMP_DG_0004  66887  106845 
DUMP_DG     DUMP_DG_0005  59264  7561   
DUMP_DG     DUMP_DG_0006  58953  6996   
DUMP_DG     DUMP_DG_0007  73000  10251  
DUMP_DG     DUMP_DG_0008  223    66383  
DUMP_DG     DUMP_DG_0009  223    66820
DUMP_DG     DUMP_DG_0010  66421  8176   
DUMP_DG     DUMP_DG_0011  58860  8546   

 

Group_Name  Dsk_Name      Reads  Writes 
DUMP_DG     DUMP_DG_0000  0.00   32.20  
DUMP_DG     DUMP_DG_0001  0.00   43.80  
DUMP_DG     DUMP_DG_0002  0.00   32.60  
DUMP_DG     DUMP_DG_0003  0.00   35.20  
DUMP_DG     DUMP_DG_0004  35.20  0.20   
DUMP_DG     DUMP_DG_0005  30.40  1.00   
DUMP_DG     DUMP_DG_0006  30.40  0.00   
DUMP_DG     DUMP_DG_0007  28.80  11.40  
DUMP_DG     DUMP_DG_0008  0.00   39.00  
DUMP_DG     DUMP_DG_0009  0.00   27.40  
DUMP_DG     DUMP_DG_0010  27.40  0.20   
DUMP_DG     DUMP_DG_0011  33.60  11.80

 

 

Il semble que oui d'un point de vue Oracle. Et d’un point de vue système ?

 

# iostat –Mxnzt 5
[…]
    0.0  14.4   0.0  14.4  0.0  0.2  0.0  14.5   0   5 c1t5000097408231998d7
    0.0  26.4   0.0  14.5  0.0  0.2  0.0   8.5   0   6 c1t5000097408231998d6
    0.0  14.4   0.0  14.4  0.0  0.2  0.0  15.4   0   6 c1t5000097408231998d5
    0.0  16.2   0.0  16.0  0.0  0.2  0.0  15.0   0   6 c1t5000097408231998d4
   16.0  11.6  16.0   0.0  0.0  0.3  0.0  10.9   0   9 c1t500009740823ED98d7
   16.0   0.0  16.0   0.0  0.0  0.2  0.0  11.4   0   5 c1t500009740823ED98d6
   12.8   0.8  12.8   0.0  0.0  0.2  0.0  17.4   0   7 c1t500009740823ED98d5
   16.0   0.2  16.0   0.0  0.0  0.2  0.0  10.5   0   4 c1t500009740823ED98d4
   16.0  11.6  16.0   0.0  0.0  0.3  0.0  10.7   0   9 c3t500009740823EDA4d7
   16.0   0.0  16.0   0.0  0.0  0.2  0.0  11.4   0   5 c3t500009740823EDA4d6
   12.8   0.2  12.8   0.0  0.0  0.2  0.0  17.5   0   7 c3t500009740823EDA4d5
   16.0   0.2  16.0   0.0  0.0  0.2  0.0  10.4   0   4 c3t500009740823EDA4d4
    0.0  14.4   0.0  14.4  0.0  0.2  0.0  14.5   0   5 c3t50000974082319A4d7
    0.0  26.2   0.0  14.5  0.0  0.2  0.0   8.5   0   6 c3t50000974082319A4d6
    0.0  14.4   0.0  14.4  0.0  0.2  0.0  15.3   0   6 c3t50000974082319A4d5
    0.0  16.2   0.0  16.0  0.0  0.2  0.0  15.0   0   6 c3t50000974082319A4d4
   15.2   0.0  15.2   0.0  0.0  0.3  0.0  18.0   0   8 c1t500009740823ED98d13
   16.0   0.4  16.0   0.0  0.0  0.3  0.0  16.7   0   8 c1t500009740823ED98d12
   15.2   0.0  15.2   0.0  0.0  0.3  0.0  17.6   0   8 c3t500009740823EDA4d13
   16.4   0.0  16.0   0.0  0.0  0.3  0.0  17.9   0   9 c3t500009740823EDA4d12
    0.0  16.2   0.0  16.0  0.0  0.2  0.0  15.0   0   6 c3t50000974082319A4d13
    0.0  17.8   0.0  17.6  0.0  0.3  0.0  14.4   0   7 c3t50000974082319A4d12
    0.0  16.2   0.0  16.0  0.0  0.3  0.0  15.5   0   6 c1t5000097408231998d13
    0.0  17.8   0.0  17.6  0.0  0.3  0.0  14.9   0   7 c1t5000097408231998d12
[…]

 

 

Effectivement il y a bien des IO physiques. (pour information, les luns ci-dessus appartiennent bien au diskgroup ASM dump_dg).

 

Pourquoi la resynchronisation dure aussi longtemps alors que vue d'Oracle, on écrit uniquement les « metadatas » !? C’est vraiment bizarre. Vérifions avec Dtrace ce qui se passe vraiment lors des lectures et écritures.

 

# dtrace -n 'io:::start { @[pid] = count(); }'
dtrace: description 'io:::start ' matched 6 probes
^C 

    13029                4
    13184                5
    13242                8
     2637               27
    13031              161
    13763             1256

 

# dtrace -n 'io:::start /pid == 13763/ \
{ @["disk I/O operation", args[1]->dev_pathname, \
args[0]->b_flags & B_READ ? "R" : "W"] \

=  quantize(args[0]->b_lblkno); }’
dtrace: description 'io:::start ' matched 6 probes
^C  

  disk I/O operation           /devices/pseudo/emcp@96:g,blk         R                                                     

           value  ------------- Distribution ------------- count   
        33554432 |                                         0           
        67108864 |@                                        8           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  288     
       268435456 |                                         0                        

 

  disk I/O operation           /devices/pseudo/emcp@24:g,blk         W                                                    

           value  ------------- Distribution ------------- count   
        33554432 |                                         0           
        67108864 |@@@@                                     32      
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     280     
       268435456 |                                         0           

 

  disk I/O operation          /devices/pseudo/emcp@25:g,blk          W                                                    

         value  ------------- Distribution ------------- count   
        33554432 |                                         0           
        67108864 |@@@                                      24          
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    288     
       268435456 |                                         0           

 

  disk I/O operation         /devices/pseudo/emcp@94:g,blk           R                                                    

           value  ------------- Distribution ------------- count   
        33554432 |                                         0           
        67108864 |@                                        8           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  296     
       268435456 |                                         0           

 

  disk I/O operation         /devices/pseudo/emcp@26:g,blk           W                                                    
           value  ------------- Distribution ------------- count   
        33554432 |                                         0           
        67108864 |@@@                                      24          
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    296     
       268435456 |                                         0           

 

  disk I/O operation         /devices/pseudo/emcp@27:g,blk           W                                                     

           value  ------------- Distribution ------------- count    
        33554432 |                                         0            
        67108864 |@@@                                      24          
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    296     
       268435456 |                                         0        

 

  disk I/O operation        /devices/pseudo/emcp@613:g,blk           W                                                    

         value  ------------- Distribution ------------- count   
         67108864 |                                         0           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 312     
       268435456 |                                         0           

 

  disk I/O operation       /devices/pseudo/emcp@913:g,blk            R                                                    

           value  ------------- Distribution ------------- count   
        67108864 |                                         0           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 320     
       268435456 |                                         0           

 

  disk I/O operation      /devices/pseudo/emcp@97:g,blk              R                                                    

           value  ------------- Distribution ------------- count  
        33554432 |                                         0           
        67108864 |@@                                       16          
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   320     
       268435456 |                                         0           

 

  disk I/O operation     /devices/pseudo/emcp@95:g,blk               R                                                     

           value  ------------- Distribution ------------- count  
        33554432 |                                         0          
        67108864 |@                                        8           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  328     
       268435456 |                                         0               

 

  disk I/O operation     /devices/pseudo/emcp@912:g,blk               R                                                     

           value  ------------- Distribution ------------- count   
        67108864 |                                         0           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 344     
       268435456 |                                         0           

 

  disk I/O operation     /devices/pseudo/emcp@612:g,blk               W                                                    

           value  ------------- Distribution ------------- count   
        67108864 |                                         0           
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 360     
       268435456 |                                         0           

 

 

On lit et on écrit toujours sur les mêmes blocks !!

 

Si nous résumons : l’utilisation du « fastresync » sur un diskgroup ASM ayant un ou des volume(s) ACFS semble poser problème : on synchronise bien les metadatas mais cette opération « boucle » beaucoup trop longtemps (plus d'une heure de resynchronisation alors qu'aucune modification a eu lieu). Un petit call chez Oracle pour avoir quelques précisons…

 

Je remercie David et Yahya (encore) pour notre analyse commune sur ce problème. “Hardware and software work together” : le slogan suivant s’applique particulièrement bien à ce contexte.

 

Par gloumps - Publié dans : kernel
Ecrire un commentaire - Voir les 1 commentaires

Dimanche 10 février 2013 7 10 /02 /Fév /2013 20:14

 

Lors d'un précédent article, j'ai traité la mise en place d'un serveur AI personnalisé pour l'architecture Sparc (déploiement via Wanboot). Comme convenu, je vais traité ici la mise en place d'un serveur AI mais sur l'architecture x86. La différence entre ces deux architectures (d'un point vue installation) se situe principalement sur la phase d'initialisation juste avant le début de l'installation.

 

Sur une architecture x86, la phase d'initialisation est généralement exécutée par le couple pxe / dhcp. Il est donc nécessaire de configurer un serveur dhcp permettant d'interpréter la requête pxe que le client enverra. Il peut s'agir d'un serveur dédié ou mutualisé avec le serveur AI. Dans mon exemple ci-dessous, il n'y a qu'un serveur pour la configuraton dhcp et AI.

 

Un choix s'offre à nous concernant le type de serveur dhcp. Il est possible d'utiliser le serveur dhcp de l'ISC ou alors le serveur dhcp de Solaris. La configuration d'un serveur dhcp ISC est automatique si celui-ci se trouve sur le serveur AI. Toutefois, je préfére utiliser le serveur dhcp Solaris.

 

Il faut installer les package dhcp et ai sur le serveur d'installation depuis notre serveur de repos (pour créer les repos lire cet article). Ensuite il suffit d'initialiser le serveur dhcp avec les bonnes informations.

 

# pkg install install/installadm SUNWdhcs

 

# /usr/sbin/dhcpconfig -D -r SUNWfiles -p /var/dhcp
Created DHCP configuration file.
Created dhcptab.
Added "Locale" macro to dhcptab.
Added server macro to dhcptab - aiserver.
DHCP server started.

 

# dhcpconfig -N 192.168.10.0 -m 255.255.255.0 -t 192.168.10.1
Added network macro to dhcptab - 192.168.10.0.
Created network table. 

 

# pntadm -L
192.168.10.0

 

 

Une fois ces étapes effectuées, il faut initialiser le service d'installation pour les clients x86.

 

# installadm create-service –a i386
Warning: Service svc:/network/dns/multicast:default is not online.
   Installation services will not be advertised via multicast DNS.

 

Creating service from: pkg:/install-image/solaris-auto-install
OK to use subdir of /export/auto_install to store image? [y/N]: y
DOWNLOAD              PKGS         FILES    XFER (MB)   SPEED
Completed              1/1       514/514  292.3/292.3 11.1M/s

 

PHASE                                      ITEMS
Installing new actions                   661/661
Updating package state database             Done
Updating image state                        Done
Creating fast lookup database               Done
Reading search index                        Done
Updating search index                        1/1

 

Creating i386 service: solaris11_1-i386
Image path: /export/auto_install/solaris11_1-i386

 

Refreshing install services
Warning: mDNS registry of service solaris11_1-i386 could not be verified.

 

Creating default-i386 alias

 

Setting the default PXE bootfile(s) in the local DHCP configuration
to:
bios clients (arch 00:00):  default-i386/boot/grub/pxegrub2
uefi clients (arch 00:07):  default-i386/boot/grub/grub2netx64.efi

 

Unable to update the DHCP SMF service after reconfiguration: DHCP
server is in an unexpected state: action [enable] state [offline]

 

The install service has been created and the DHCP configuration has
been updated, however the DHCP SMF service requires attention. Please
see dhcpd(8) for further information.

 

Refreshing install services
Warning: mDNS registry of service default-i386 could not be verified.

 

 

Le service pour les clients x86 est maintenant disponible.

 

# installadm list -m

Service/Manifest Name  Status   Criteria
---------------------  ------   --------

default-i386
   orig_default        Default  None

solaris11_1-i386
   orig_default        Default  None

 

 

Concernant la personnalisation, je vous renvoie au précédent article pour plus de détails. On crée un manifest spécifique en utilisant les commandes suivantes.

 

# installadm export --service solaris11_1-i386 \
--manifest orig_default \

--output /export/auto_install/manifests/sol11.1-i386-001
# vi /export/auto_install/manifests/sol11.1-i386-001
# installadm create-manifest \
-f /export/auto_install/manifests/sol11.1-i386-001 \

-n solaris11_1-i386 -m sol11.1-i386-001 -d

 

 

En cas d'autre modification sur ce manifest, on utilise les commandes suivantes.

 

# vi /export/auto_install/manifests/sol11.1-i386-001
# installadm update-manifest \
-f /export/auto_install/manifests/sol11.1-i386-001 \

-n solaris11_1-i386 -m sol11.1-i386-001

 

 

Pour éviter de garder le service et le manifest par défaut, on nettoie un peu la configuration.

 

# installadm delete-service default-i386
# installadm delete-manifest -n solaris11_1-i386 -m orig_default

 

 

On passe maintenant à la création du profile pour un client donné.

 

# sysconfig create-profile -o /export/auto_install/ref/profile.xml
# cd /export/auto_install/ref
# cp profile.xml ../clients/i386-01.xml
# vi /export/auto_install/clients/i386-01.xml

 

# installadm create-profile \
-f /export/auto_install/clients/i386-01.xml \
-n solaris11_1-i386 \

-p i386-01 -c mac="00:xx:xx:xx:xx:04"

 

 

Lors de la création du client, j'initialise la redirection série ainsi que le mode debug (connexion ssh distante pendant l'installation). Pour plus de détails sur la redirection série je vous invite à lire cet autre article.

 

# installadm create-client -e 00xxxxxxxx04 -n solaris11_1-i386 \
-b console=ttya,livessh=enable,install_debug=enable

Warning: Service svc:/network/dns/multicast:default is not online.
   Installation services will not be advertised via multicast DNS.
Adding host entry for 00:xx:xx:xx:xx:04 to local DHCP configuration.

 

Local DHCP configuration complete, but the DHCP server SMF service is
offline. To enable the changes made, enable:
svc:/network/dhcp/server:ipv4.
Please see svcadm(1M) for further information.

 

 

La configuration du serveur AI est terminée et un client a été généré (profile spécifique).

 

# installadm list -c -p -m

 
Service Name      Client Address    Arch   Image Path
------------      --------------    ----   ----------
solaris11_1-i386 00:xx:xx:xx:xx:04  i386  /export/auto_install/solaris11_1-i386

 

Service/Manifest Name  Status   Criteria
---------------------  ------   --------

solaris11_1-i386
   sol11.1-i386-001   Default  None 

 

Service/Profile Name  Criteria
--------------------  --------

solaris11_1-i386
   i386-01      mac = 00:xx:xx:xx:xx:04

 

 

Reste la configuration dhcp pour ce client.

 

# pntadm -A 192.168.10.123 -i 0100xxxxxxxx04 \
-m 0100xxxxxxxx04 -f "PERMANENT+MANUAL" 192.168.10.0

 

# pntadm -P 192.168.10.0 | grep 0100xxxxxxxx04
0100xxxxxxxx04  03  192.168.10.5  192.168.10.123   Zero   0100xxxxxxxx04

 

# dhtadm -g -A -m 0100xxxxxxxx04 -d \
":Include=`uname -n`:BootSrvA=192.168.10.5:BootFile=0100xxxxxxxx04:"

 

 

L'installation du client peut donc commencer. Depuis l'ILO de ce client x86, on sélectionne notre carte réseau comme périphérique de boot puis dane le menu de grub on sélectionne le choix 2 pour lancer l'installation. 

 

SunOS Release 5.11 Version 11.1 64-bit
Copyright (c) 1983, 2012, Oracle and/or its affiliates. All rights reserved.
Remounting root read/write
Probing for device nodes ...
Preparing network image for use

 

Downloading solaris.zlib
--2013-01-30 20:51:33--  http://192.168.10.5:5555//export/auto_install/solaris11_1-i386/solaris.zlib
Connecting to 192.168.10.5:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 135808512 (130M) [text/plain]
Saving to: `/tmp/solaris.zlib'

100%[======================================>] 135,808,512 57.3M/s   in 2.3s   

2013-01-30 20:51:35 (57.3 MB/s) - `/tmp/solaris.zlib' saved [135808512/135808512]

 

Downloading solarismisc.zlib
--2013-01-30 20:51:35--  http://192.168.10.5:5555//export/auto_install/solaris11_1-i386/solarismisc.zlib
Connecting to 192.168.10.5:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 11935744 (11M) [text/plain]
Saving to: `/tmp/solarismisc.zlib' 

100%[======================================>] 11,935,744  58.3M/s   in 0.2s   

2013-01-30 20:51:36 (58.3 MB/s) - `/tmp/solarismisc.zlib' saved [11935744/11935744]

 

Downloading .image_info
--2013-01-30 20:51:36--  http://192.168.10.5:5555//export/auto_install/solaris11_1-i386/.image_info
Connecting to 192.168.10.5.:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 228 [text/plain]
Saving to: `/tmp/.image_info'

100%[======================================>] 228         --.-K/s   in 0s     

2013-01-30 20:51:36 (19.5 MB/s) - `/tmp/.image_info' saved [228/228]

 

Done mounting image
Configuring devices.
Hostname: i386-01
Setting debug mode to enable
Service discovery phase initiated
Service name to look up: solaris11_1-i386
Service discovery over multicast DNS failed
Service solaris11_1-i386 located at 192.168.10.5:5555 will be used
Service discovery finished successfully
Process of obtaining install manifest initiated
Using the install manifest obtained via service discovery

 

i386-01 console login:
Automated Installation started
The progress of the Automated Installation will be output to the console
Detailed logging is in the logfile at /system/volatile/install_log

 

Press RETURN to get a login prompt at any time.

 

Installer will be run in debug mode
20:52:02    Using XML Manifest: /system/volatile/ai.xml
20:52:02    Using profile specification: /system/volatile/profile
20:52:02    Using service list file: /var/run/service_list
20:52:02    Starting installation.
20:52:02    0% Preparing for Installation
20:52:03    100% manifest-parser completed.
20:52:03    0% Preparing for Installation
20:52:03    1% Preparing for Installation
20:52:03    2% Preparing for Installation
20:52:03    4% Preparing for Installation
20:52:07    6% target-discovery completed.
20:52:07    Selected Disk(s) : c8t0d0
20:52:07    10% target-selection completed.
20:52:07    12% ai-configuration completed.
20:52:07    14% var-share-dataset completed.
20:52:30    16% Beginning IPS transfer
20:52:30    Creating IPS image
20:52:34     Startup: Retrieving catalog 'solaris' ... Done
20:52:36     Startup: Caching catalogs ... Done
20:52:37     Startup: Refreshing catalog 'site' ... Done
20:52:37     Startup: Refreshing catalog 'solaris' ... Done
20:52:40     Startup: Caching catalogs ... Done
20:52:40    Installing packages from:
20:52:40        solaris
20:52:40            origin:  http://192.168.10.5:8000/
20:52:40        site
20:52:40            origin:  http://192.168.10.5:8001/
20:52:41     Startup: Refreshing catalog 'site' ... Done
20:52:41     Startup: Refreshing catalog 'solaris' ... Done
20:52:44    Planning: Solver setup ... Done
20:52:45    Planning: Running solver ... Done
20:52:45    Planning: Finding local manifests ... Done
20:52:45    Planning: Fetching manifests:   0/408  0% complete
20:52:53    Planning: Fetching manifests: 100/408  24% complete
[…]
20:53:11    Planning: Fetching manifests: 408/408  100% complete
20:53:22    Planning: Package planning ... Done
20:53:23    Planning: Merging actions ... Done
20:53:26    Planning: Checking for conflicting actions ... Done
20:53:28    Planning: Consolidating action changes ... Done
20:53:30    Planning: Evaluating mediators ... Done
20:53:33    Planning: Planning completed in 52.04 seconds
20:53:33    Please review the licenses for the following packages post-install:
20:53:33      runtime/java/jre-7                       (automatically accepted)
20:53:33      consolidation/osnet/osnet-incorporation  (automatically accepted,
20:53:33                                                not displayed)
20:53:33    Package licenses may be viewed using the command:
20:53:33      pkg info --license <pkg_fmri>
20:53:34    Download:     0/60319 items    0.0/822.8MB  0% complete
[…]
21:00:44    Download: 60010/60319 items  822.0/822.8MB  99% complete (650k/s)
21:00:45    Download: Completed 822.79 MB in 431.69 seconds (1.9M/s)
21:01:00     Actions:     1/85295 actions (Installing new actions)
21:01:01    16% Transferring contents
21:01:01    19% Transferring contents
21:01:05     Actions: 13914/85295 actions (Installing new actions)
21:01:06    45% Transferring contents
21:01:10     Actions: 18060/85295 actions (Installing new actions)
21:01:15     Actions: 18534/85295 actions (Installing new actions)
[…]
21:09:55     Actions: 83977/85295 actions (Installing new actions)
21:10:00     Actions: 84781/85295 actions (Installing new actions)
21:10:01     Actions: Completed 85295 actions in 540.82 seconds.
21:10:01    Finalize: Updating package state database ...  Done
21:10:03    Finalize: Updating image state ...  Done
21:10:15    Finalize: Creating fast lookup database ...  Done
21:10:25    Version mismatch:
21:10:25    Installer build version: pkg://solaris/entire@0.5.11,5.11-0.175.1.0.0.24.2:20120919T190135Z
21:10:25    Target build version: pkg://solaris/entire@0.5.11,5.11-0.175.1.1.0.4.0:20121106T001344Z
21:10:25    46% initialize-smf completed.
21:10:27    Setting console boot device property to ttya
21:10:27    Disabling boot loader graphical splash
21:10:27    Installing boot loader to devices: ['/dev/rdsk/c8t0d0s1']
21:10:32    Setting boot devices in firmware
21:10:32    54% boot-configuration completed.
21:10:32    55% update-dump-adm completed.
21:10:32    57% setup-swap completed.
21:10:32    58% device-config completed.
21:10:33    60% apply-sysconfig completed.
21:10:33    61% transfer-zpool-cache completed.
21:10:51    90% boot-archive completed.
21:10:51    92% transfer-ai-files completed.
21:10:52    99% create-snapshot completed.
21:10:52    Automated Installation succeeded.
21:10:52    System will be rebooted now
Automated Installation finished successfully
Auto reboot enabled. The system will be rebooted now
Log files will be available in /var/log/install/ after reboot
Jan 30 21:10:56 i386-01 reboot: initiated by root
WARNING: Fast reboot is not supported on this platform since some BIOS routines are in RAM
syncing file systems... done
rebooting...

 

Plus d'excuse maintenant, vous pouvez installer un serveur AI pour déployer aussi bien des serveurs Sparc que des serveurs i386.

 

Par gloumps - Publié dans : administration
Ecrire un commentaire - Voir les 0 commentaires

Jeudi 7 février 2013 4 07 /02 /Fév /2013 20:41

 

Les apparences sont quelques fois trompeuses… Petite démonstration confirmant cet adage.

 

Situons le contexte : plusieurs DBA Oracle nous remontent un incident sur un de leur serveur. Le symptôme étant le suivant : connexion impossible. Après une rapide vérification le diagnostic initiale semble être le bon. Petite connexion au déport console du serveur et me voilà devant un message des plus explicite « Unable to fork ». Hop, je provoque un petit panic et en avant pour une petite analyse.

 

Avant de me lancer tête baissée dans l’analyse de ce core, je m’intéresse aux logs du serveur en recherchant le pattern fork.

 

Jan 22 13:05:43 myserver sshd[7716]: [ID 800047 auth.error] error: fork: Error 0
Jan 22 13:08:06 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance svc:/network/nrpe/tcp:default: Resource temporarily unavailable
Jan 22 13:08:36 eqds2dstdby002 last message repeated 1 time
Jan 22 13:09:59 myserver inetd[7805]: [ID 702911 daemon.error] Unable to fork inetd_start method of instance svc:/network/nrpe/tcp:default: Resource temporarily unavailable

 

A partir de 13:05, il semble que le serveur ne pouvait plus « forker » de nouveau process. Je vais faire parler le core !?

 

# cd /var/crash/myserver
# savecore –f vmdump.0
savecore -f vmdump.0
savecore: System dump time: Tue Jan 22 14:54:46 2013

 

savecore: saving system crash dump in /var/crash/myserver/{unix,vmcore}.0
Constructing namelist /var/crash/myserver/unix.0
Constructing corefile /var/crash/myserver/vmcore.0
8:36  92% done
9:22 100% done: 3571069 of 3571069 pages saved

 

# mdb –k 0
Loading modules: [ unix genunix specfs dtrace zfs sd mpt px ssd fcp fctl sockfs ip hook neti qlc dls sctp arp usba md cpc fcip random crypto logindmux ptm ufs sppp ipc nfs lofs ]
> fork_fail_pending/D
fork_fail_pending:
fork_fail_pending:        1

 

Il s’agit bien d’un problème de fork. Combien de processus générés ?

 

> ::ps !grep -v FLAGS | wc -l
   29952

 

29952 processus en machine !! Sachant que la limite haute se situe vers 30000, je comprends mieux le problème. Essayons dans savoir plus. Quel est le contributeur ? S’agit-il d’une « mauvaise bouche » dans un script (merci la fork bomb)  ?

 
> ::ps
S    PID   PPID   PGID    SID    UID      FLAGS             ADDR NAME
R      0      0      0      0      0 0x00000001 00000000018b09c0 sched
R   4510      0      0      0      0 0x00020001 00000600e4766018 zpool-oradg00
R     92      0      0      0      0 0x00020001 00000600b4821960 zpool-spool
R     88      0      0      0      0 0x00020001 00000600b4823290 zpool-dump
R     86      0      0      0      0 0x00020001 00000600b21b6ca8 zpool-asmdg00
R      7      0      0      0      0 0x00020001 00000600b21b9270 vmtasks
R      3      0      0      0      0 0x00020001 000006009bdb4008 fsflush
R      2      0      0      0      0 0x00020001 000006009bdb4ca0 pageout
Z      1      0      0      0      0 0x4a004000 000006009bdb5938 init
Z   4712      1     11     11      0 0x5a006002 0000060146e6c0d0 p_ctscd
Z   4713      1     11     11      0 0x5a006002 0000060153fa8670 p_ctscs
R   7637      1   7637   7637      0 0x4a014000 00000600c9be4cf0 sac
R   7695   7637   7637   7637      0 0x4a014000 00000600c98b8cd8 ttymon
R  11035      1     11     11      0 0x4a004000 00000600cdd519b8 uce_agent.sh
R  15869  11035     11     11      0 0x4a004000 00000600b2b805e0 uce_agent.bin
Z  24884      1  24884  24884    100 0x4a004002 0000030597a799a0 oracle
Z   1449      1   1449   1449    100 0x4a004002 0000030597a28050 oracle
Z  18483      1  18483  18483    100 0x4a004002 0000030597a7a638 oracle
Z   5461      1   5461   5461    100 0x4a004002 0000030597a7d998 oracle
Z  28198      1  28198  28198    100 0x4a004002 0000030597a7c068 oracle
Z  21932      1  21932  21932    100 0x4a004002 0000030597a7cd00 oracle
Z  14770      1  14770  14770    100 0x4a004002 0000030597a37368 oracle
Z   8999      1   8999   8999    100 0x4a004002 0000030597aad938 oracle
[…]
Z  13641      1  13641  13641    100 0x4a004002 0000030597aa3280 oracle
Z  12707      1  12707  12707    100 0x4a004002 0000030597aa4018 oracle
>> More [<space>, <cr>, q, n, c, a] ?

 

A première vue Il semble y avoir beaucoup de processus « oracle ».  Piste intéressante, j’investigue.

 

> ::ps !grep -c oracle
29684

 

Confirmation qu’il s’agit bien du contributeur « oracle ». J’essaye dans savoir un peu plus.

 

> ::ptree
00000000018b09c0  sched
     00000600e4766018  zpool-oradg00
     00000600b4821960  zpool-spool
     00000600b4823290  zpool-dump
     00000600b21b6ca8  zpool-asmdg00
     00000600b21b9270  vmtasks
     000006009bdb4008  fsflush
     000006009bdb4ca0  pageout
     000006009bdb5938  init
          0000060146e6c0d0  p_ctscd
          0000060153fa8670  p_ctscs
          00000600c9be4cf0  sac
               00000600c98b8cd8  ttymon
          00000600cdd519b8  uce_agent.sh
               00000600b2b805e0  uce_agent.bin
          0000030597a799a0  oracle
          0000030597a28050  oracle
          0000030597a7a638  oracle
          0000030597a7d998  oracle
          0000030597a7c068  oracle
          0000030597a7cd00  oracle
          0000030597a37368  oracle
          0000030597aad938  oracle     
[…]

 

Tous les processus « oracle » ont comme père le processus init. Il s’agit vraisemblablement d’un nombre important de « sessions oracle » (et non pas une fork bomb). Je vérifie.

 

> ::ps -ft !grep oracle
Z  24884  1  24884  24884  100 0x4a004002 0000030597a799a0 oracleBASE (LOCAL=NO)
Z   1449  1   1449   1449  100 0x4a004002 0000030597a28050 oracleBASE (LOCAL=NO)
Z  18483  1  18483  18483  100 0x4a004002 0000030597a7a638 oracleBASE (LOCAL=NO)
Z   5461  1   5461   5461  100 0x4a004002 0000030597a7d998 oracleBASE (LOCAL=NO)
Z  28198  1  28198  28198  100 0x4a004002 0000030597a7c068 oracleBASE (LOCAL=NO)
Z  21932  1  21932  21932  100 0x4a004002 0000030597a7cd00 oracleBASE (LOCAL=NO)
Z  14770  1  14770  14770  100 0x4a004002 0000030597a37368 oracleBASE (LOCAL=NO)
Z   8999  1   8999   8999  100 0x4a004002 0000030597aad938 oracleBASE (LOCAL=NO)
Z   2874  1   2874   2874  100 0x4a004002 0000030597a7e630 oracleBASE (LOCAL=NO)
Z  29899  1  29899  29899  100 0x4a004002 0000030597a88050 oracleBASE (LOCAL=NO)
Z  26317  1  26317  26317  100 0x4a004002 0000030597a7f2c8 oracleBASE (LOCAL=NO)
Z  23244  1  23244  23244  100 0x4a004002 0000030597a80cf8 oracleBASE (LOCAL=NO)
Z  20412  1  20412  20412  100 0x4a004002 0000030597a81990 oracleBASE (LOCAL=NO)
Z  16689  1  16689  16689  100 0x4a004002 0000030597a82628 oracleBASE (LOCAL=NO)
[…]

 

 

Bingo ! J’ai un coupable… Un petit paasage chez les DBA Oracle pour leur expliquer que l’incident survenu sur le serveur (indisponibilité) provient de chez eux.

 

<troll><mode Adrien> Encore les DBA, les nuls !! Un bon DBA est un DBA … </mode Adrien></troll>

 

J’ai dit quoi déjà : les apparences sont quelques fois trompeuses…

 

<troll> Adrien, calme me toi et lis la suite </troll>

 

En regardant d’un peu plus près le retour des commandes « ps », un premier élément me choque.

 

> ::ps -ft
[…]
Z  24884  1  24884  24884  100 0x4a004002 0000030597a799a0 oracleBASE (LOCAL=NO)
Z   1449  1   1449   1449  100 0x4a004002 0000030597a28050 oracleBASE (LOCAL=NO)
Z  18483  1  18483  18483  100 0x4a004002 0000030597a7a638 oracleBASE (LOCAL=NO)
Z   5461  1   5461   5461  100 0x4a004002 0000030597a7d998 oracleBASE (LOCAL=NO)
[…]

 

A première vue il s’agit de processus « zombie ».  Strange… Combien de processus zombie pour cette base ? Existe-t-il d’autres processus zombie ?

 

> ::ps -ft !grep oracleBASE | grep -c ^Z
28773

> ::ps -ft !grep ^Z | grep -cv oracleBASE
469

 

Attention un processus zombie consomme une entrée dans la table des processus.

 

On a related note, the signal flow explains why zombie processes cannot be killed (any horror movie fan knows you can’t kill a zombie). A process must be executing in order to take delivery of a signal. A zombie process is, by definition, a process that has terminated. It exists only as a process table entry, with all of its execution state having been freed by the kernel (see preap(1) for cleaning up zombie processes).

 

En détaillant un peu les autres processus zombie un autre indice me choque rapidement.

 

> ::ps –ft !grep ^Z | grep –v BASE
Z      1   0      0      0    0 0x4a004000 000006009bdb5938 /sbin/init
Z  29265   1  29265  29265  100 0x4a004002 000003059798f2f8 oracle+ASM (LOCAL=NO)
Z  17389   1  17389  17389  100 0x4a004002 000003059791c088 oracleXXX (LOCAL=NO)
Z  10068   1  10068  10068  100 0x4a004002 00000305979172f8 oracleXXZ (LOCAL=NO)
Z   8308   1   8308   8308  100 0x4a004002 0000030597924d10 oracleXYZ (LOCAL=NO)
Z   6559   1   6559   6559  100 0x4a004002 0000030597930060 oracleZWX (LOCAL=NO)
Z   1229   1   1229   1229  100 0x4a004002 00000305978e8100 oracleZSD (LOCAL=NO)
Z  16366   1  16366  16366  100 0x4a004002 00000305977c0060 oracleWWW (LOCAL=NO)
Z   2621   1   2621   2621  100 0x4a004002 0000030597713340 oracleQQQ (LOCAL=NO)
Z  25811   1  25519  25519  100 0x4a004002 0000030597640d28 who am i
[…]

 

Le process « init » est dans l’état « zombie »… C’est assez surprenant !? Normalement un processus zombie est un processus terminé en attente d’un signal wait(2).

 

Regardless of which event causes the process to terminate, the kernel exit function is ultimately executed, freeing whatever resources have been allocated to the process, such as the address space mappings, open files, etc., and setting the process state to SZOMB, or the zombie state. A zombie process is one that has exited and that requires the parent process to issue a wait(2) system call to gather the exit status. The only kernel resource that a process in the zombie state is holding is the process table slot. Successful execution of a wait(2) call frees the process table slot. Orphaned processes are inherited by the init process solely for this purpose.

 

Mais s’agissant du processus init qui va lui envoyer le signal wait(2) ?

 

L’état du processus « init » semble inquiétant mais pour le moment, il n’existe pas encore de relation entre l’incident de fork et l’état du processus « init ». Y’a-t-il une information dans le buffer de messages concernant le process init ?

 

> ::msgbuf !grep init
NOTICE: core_log: init[1] core dumped: /var/core/core_myserver_init_0_0_1358854223_1
WARNING: init(1M) core dumped on signal 11: restarting automatically
WARNING: exec(/sbin/init) failed with errno 48.
WARNING: failed to restart init(1M) (err=48): system reboot required

 

Le processus init a eu un petit problème (signal SIGSEGV - Segmentation Fault) et n’a pas été réactivé correctement (exec failed – errno 48). Le problème du buffer de message c’est qu’il n’y a pas de timestamp. Du coup difficile de dire si il y a un rapport ou non avec mon incident « fork ».

 

Un petit passage par la log système est nécessaire.

 

Jan 22 12:30:24 myserver genunix: [ID 603404 kern.notice] NOTICE: core_log: init[1] core dumped: /var/core/core_myserver_init_0_0_1358854223_1
Jan 22 12:30:24 myserver genunix: [ID 894729 kern.warning] WARNING: init(1M) core dumped on signal 11: restarting automatically
Jan 22 12:30:24 myserver genunix: [ID 923222 kern.warning] WARNING: exec(/sbin/init) failed with errno 48.
Jan 22 12:30:24 myserver genunix: [ID 404865 kern.warning] WARNING: failed to restart init(1M) (err=48): system reboot required

 

L’incident du « fork » se situe environ 35 minutes après l’incident du processus init… Quelle est la date de création de ces processus zombie ? Proviennent -ils d’avant l’incident du processus init ou pas ?

 

J’ai écrit un petit script pour obtenir le timestamp de création des processus (c’est pas très élégant mais ça fonctionne).

 

# cat /tmp/time_process_zombie
echo "::ps !grep ^Z" | mdb -k 0 | awk '{print $8}' > ps$$

while read proc
do
        echo $proc | awk '{print $1}'
        echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0 vmcore.0
done < ps$$

 

# cd /var/crash/myserver
# sh /tmp/bruno > liste_zombie

 

 

# cat /tmp/time_process_run
echo "::ps !grep ^R" | mdb -k 0 | awk '{print $8}' > ps$$ 

while read proc
do
        echo $proc | awk '{print $1}'
        echo $proc | awk '{print $1,"::print proc_t p_user.u_start.tv_sec"}' | mdb unix.0 vmcore.0
done < ps$$

 

# cd /var/crash/myserver
# sh /tmp/time_process_run > liste_run

 

 

Quelques observations après l’analyse des résultats :

 

  • Seulement 3 processus créés après l’incident du processus « init » (bien entendu ces processus n’ont pas « init » comme père et celui-ci (leur père) n’est pas dans l’état zombie).
  • Plus de 29300 processus zombie ont été créés à partir du 22 janvier 12:30:00.
  • En date du 22 janvier, le premier processus zombie a démarré vers  « 2013 Jan 22 12:05:33 ».

 

> 00000600dd4b99c8::ps -ft
S   PID PPID  PGID   SID UID      FLAGS             ADDR NAME
Z 11891    1 11891 11891   0 0x42000002 00000600dd4b99c8 /usr/lib/rcm/rcm_daemon

 

Il s’agit du deamon rcm_deamon. C’est quoi ce truc ? RCM « Reconfiguration Coordination Manager » est un framework qui manage la suppression automatique de composants du système.

 

The Reconfiguration Coordination Manager (RCM) is the framework that manages the dynamic removal of system components. By using RCM, you can register and release system resources in an orderly manner. You can use the new RCM script feature to write your own scripts to shut down your applications, or to cleanly release the devices from your applications during dynamic reconfiguration. The RCM framework launches a script automatically in response to a reconfiguration request, if the request impacts the resources that are registered by the script.

 

Une modification récente sur le système ? Mais oui… évidement maintenant qu’on en parle : il y a eu effectivement un changement de disque SCSI sur le châssis vers 12h00. Je vérifie rapidement l’heure de l’opération.

 

Jan 22 12:02:08 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:02:08 myserver  Disconnected command timeout for Target 1
Jan 22 12:02:08 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:02:08 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:03:18 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:03:18 myserver Disconnected command timeout for Target 1
Jan 22 12:03:19 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:03:19 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:04:29 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:04:29 myserver Disconnected command timeout for Target 1
Jan 22 12:04:29 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:04:29 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:05:39 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:05:39 myserver Disconnected command timeout for Target 1
Jan 22 12:05:40 myserver scsi: [ID 243001 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:05:40 myserver mpt_check_scsi_io: IOCStatus=0x48 IOCLogInfo=0x31140000
Jan 22 12:06:42 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:42 myserver wwn for target has changed
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver  Disconnected command timeout for Target 1
Jan 22 12:06:50 myserver scsi: [ID 107833 kern.notice] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver  mpt_flush_target discovered non-NULL cmd in slot 484, tasktype 0x3
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver Cmd (0x3005fa08e00) dump for Target 1 Lun 0:
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver cdb=[ 0x25 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 0x0 ]
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_flags=0x1c000 pkt_statistics=0x0 pkt_state=0x0
Jan 22 12:06:50 myserver scsi: [ID 365881 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0):
Jan 22 12:06:50 myserver pkt_scbp=0x0 cmd_flags=0x860
Jan 22 12:06:53 myserver scsi: [ID 107833 kern.warning] WARNING: /pci@0,600000/pci@0/pci@8/pci@0/scsi@1/sd@1,0 (sd0):
Jan 22 12:06:53 myserver Corrupt label; wrong magic number
[…]
Jan 22 12:09:57 myserver genunix: [ID 408114 kern.info] /pci@0,600000/pci@0/pci@8/pci@0/scsi@1 (mpt0) quiesced
[…]

 

Que dire de plus… Le changement physique du disque semble avoir « perturber » le système au point où le processus « init » segfault. Ce type d'incident ne se produit pas souvent du coup c'est difficile de savoir ce qui doit se passer. Dans mon cas, il semble y avoir eu création d’environ 29300 processus dans un statut bizarre (zombie).

 

Je remercie Yahya pour m’avoir challengé sur cet incident. Sans lui, je serais passé à côté de l'état zombie d'init et jamais je n'aurais pensé à vérifier les dates de création des processus. Les apparences sont quelques fois trompeuses… n'oubliez pas !?

 

P.S. : Yahya est DBA Oracle...

 

 

Par gloumps - Publié dans : kernel
Ecrire un commentaire - Voir les 1 commentaires

Lundi 4 février 2013 1 04 /02 /Fév /2013 21:24

 

Après avoir créé vos repos (méthode pas-à-pas disponible dans un précédant article), il est temps de créer votre serveur AI personnalisé. Je vais découper ce sujet en deux partie, un article sur l'architecture Sparc et un autre sur l'architecture x86. Et pourquoi donc ? J'utilise deux méthodes d'initialisations différentes, wanboot pour l'architecture Sparc et la paire pxe/dhcp pour l'architecture x86. Du coup je préfère distinguer ces deux architectures.

 

Pour recevoir et interpréter la procédure d'installation d'un client Sparc (via wanboot), il faut que le serveur AI soit correctement configuré (serveur web, serveur tftp et script cgi).

 

# pkg set-publisher –M ‘*’ –G ‘*’ -P -g http://10.xx.xx.xxx:8000 solaris
# pkg install network/tftp 
install/installadm

# svccfg -s system/install/server:default setprop all_services/port = 5555
# svccfg refresh system/install/server:default
 

# mkdir /var/ai/image-server/images/cgi-bin
# chmod 777 /var/ai/image-server/images/cgi-bin
# cp -pr /usr/lib/inet/wanboot/wanboot-cgi /var/ai/image-server/images/cgi-bin
 

# svccfg –s network/tftp/udp6 setprop \
netd_start/exec=”/usr/sbin/in.tftpd -s /etc/netboot”

# svcadm refresh network/tftp/udp6
# inetadm –e network/tftp/udp6

 

Une fois ces étapes effectuées, il faut initialiser le service d'installation pour les clients Sparc.

 

# installadm create-service –a sparc
Warning: Service svc:/network/dns/multicast:default is not online.
   Installation services will not be advertised via multicast DNS.


Creating service from: pkg:/install-image/solaris-auto-install
OK to use subdir of /export/auto_install to store image? [y/N]: y

DOWNLOAD            PKGS      FILES    XFER (MB)   SPEED
Completed            1/1      45/45  237.8/237.8 11.5M/s 

PHASE                                      ITEMS
Installing new actions                   187/187
Updating package state database             Done
Updating image state                        Done
Creating fast lookup database               Done
Reading search index                        Done
Updating search index                        1/1


Creating sparc service: solaris11_1-sparc

 

Image path: /export/auto_install/solaris11_1-sparc

 

Service discovery fallback mechanism set up
Creating SPARC configuration file
Refreshing install services
Warning: mDNS registry of service solaris11_1-sparc could not be verified.

 

Creating default-sparc alias

 

Service discovery fallback mechanism set up
Creating SPARC configuration file
No local DHCP configuration found. This service is the default
alias for all SPARC clients. If not already in place, the following should
be added to the DHCP configuration:
Boot file: http://10.xx.xx.xxx:5555/cgi-bin/wanboot-cgi

 

Refreshing install services
Warning: mDNS registry of service default-sparc could not be verified.

 

Le service pour les clients Sparc est maintenant disponible.

 

# installadm list -m

Service/Manifest Name  Status   Criteria
---------------------  ------   --------

default-sparc
   orig_default        Default  None

solaris11_1-sparc
   orig_default        Default  None

 

Quelques personnalisations sont nécessaires (A vous de voir ce que vous souhaitez faire). Moi je personnalise de la manière suivante. Attention, dans le reste de la procédure, on utilise cette arborescence.

  • Le répertoire ref contient le profile de référence pour tous les clients
  • Le répertoire manifests contient les manifests (par mise à jour de Solaris 11)
  • Le répertoire clients contient les profiles personnalisés de chaque client

 

# cd /export/auto_install
# mkdir clients manifests ref

 

On crée un manifest spécifique en utilisant les commandes suivantes.

 

# installadm export --service solaris11_1-sparc \
--manifest orig_default \

--output /export/auto_install/manifests/sol11.1-sparc-001
# vi /export/auto_install/manifests/sol11.1-sparc-001
# installadm create-manifest \
-f /export/auto_install/manifests/sol11.1-sparc-001 \

-n solaris11_1-sparc -m sol11.1-sparc-001 -d

 

En cas d'autre modification sur ce manifest, on utilise les commandes suivantes.

 

# vi /export/auto_install/manifests/sol11.1-sparc-001
# installadm update-manifest \
-f /export/auto_install/manifests/sol11.1-sparc-001 \

-n solaris11_1-sparc -m sol11.1-sparc-001

 

Pour éviter de garder le service et le manifest par défaut, on nettoie un peu la configuration.

 

# installadm delete-service default-sparc
# installadm delete-manifest -n solaris11_1-sparc -m orig_default

 

On passe maintenant à la création du profile pour un client donné.

 

# sysconfig create-profile -o /export/auto_install/ref/profile.xml
# cd /export/auto_install/ref
# cp profile.xml ../clients/sparc-01.xml
# vi /export/auto_install/clients/sparc-01.xml

 

# installadm create-profile \
-f /export/auto_install/clients/sparc-01.xml \
-n solaris11_1-sparc \

-p sparc-01 -c mac="00:1x:xx:xx:xx:f2"

 

Reste la création du client.

 

# installadm create-client -e 001xxxxxxxf2 -n solaris11_1-sparc
Warning: Service svc:/network/dns/multicast:default is not online.
   Installation services will not be advertised via multicast DNS.

 

La configuration du serveur AI est terminé et un client a été généré par rapport à un manifest et un profile spécifique.

 

# installadm list -c -p -m

 
Service Name      Client Address     Arch   Image Path
------------      --------------     ----   ----------
solaris11_1-sparc 00:1x:xx:xx:xx:F2  sparc  /export/auto_install/solaris11_1-sparc

 

Service/Manifest Name  Status   Criteria
---------------------  ------   --------

solaris11_1-sparc
   sol11.1-sparc-001   Default  None 

 

Service/Profile Name  Criteria
--------------------  --------

solaris11_1-sparc
   sparc-01      mac = 00:1x:xx:xx:xx:F2

 

Depuis l'OBP du client Sparc, on configure les paramètres du wanboot et on lance l'installation.

 

{0} ok setenv network-boot-arguments  host-ip=10.xx.xx.xxx,router-ip=10.xx.xx.1,
subnet-mask=255.xxx.xxx.xxx,file=http://10.xx.xx.xxx:5555/cgi-bin/wanboot-cgi

 

{0} ok boot net - install

 

Boot device: /pci@0,600000/pci@0/pci@8/pci@0/network@2  File and args: - install
1000 Mbps full duplex  Link up
<time unavailable> wanboot info: WAN boot messages->console
<time unavailable> wanboot info: configuring /pci@0,600000/pci@0/pci@8/pci@0/network@2

 

1000 Mbps full duplex  Link up
<time unavailable> wanboot progress: wanbootfs: Read 368 of 368 kB (100%)
<time unavailable> wanboot info: wanbootfs: Download complete
Mon Dec 17 15:49:54 wanboot progress: miniroot: Read 243471 of 243471 kB (100%)
Mon Dec 17 15:49:54 wanboot info: miniroot: Download complete

 

SunOS Release 5.11 Version 11.1 64-bit
Copyright (c) 1983, 2012, Oracle and/or its affiliates. All rights reserved.
Remounting root read/write
Probing for device nodes ...
Preparing network image for use

 

Downloading solaris.zlib
--2012-12-17 16:21:37--  http://10.xx.xx.xxx:5555/export/auto_install/solaris11_1-sparc//solaris.zlib
Connecting to 10.xx.xx.xxx:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 133076480 (127M) [text/plain]
Saving to: `/tmp/solaris.zlib'

100%[======================================>] 133,076,480 49.6M/s   in 2.6s   

2012-12-17 16:21:39 (49.6 MB/s) - `/tmp/solaris.zlib' saved [133076480/133076480]

 

Downloading solarismisc.zlib
--2012-12-17 16:21:39--  http://10.xx.xx.xxx:5555/export/auto_install/solaris11_1-sparc//solarismisc.zlib
Connecting to 10.xx.xx.xxx:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 11808768 (11M) [text/plain]
Saving to: `/tmp/solarismisc.zlib'

100%[======================================>] 11,808,768  63.0M/s   in 0.2s   

2012-12-17 16:21:40 (63.0 MB/s) - `/tmp/solarismisc.zlib' saved [11808768/11808768]

 

Downloading .image_info
--2012-12-17 16:21:40--  http://10.xx.xx.xxx:5555/export/auto_install/solaris11_1-sparc//.image_info
Connecting to 10.xx.xx.xxx:5555... connected.
HTTP request sent, awaiting response... 200 OK
Length: 81 [text/plain]
Saving to: `/tmp/.image_info'

100%[======================================>] 81          --.-K/s   in 0s     

2012-12-17 16:21:40 (7.02 MB/s) - `/tmp/.image_info' saved [81/81]

 

Done mounting image
Configuring devices.
Hostname: solaris
Service discovery phase initiated
Service name to look up: solaris11_1-sparc
Service discovery over multicast DNS failed
Service solaris11_1-sparc located at 10.xx.xx.xxx:5555 will be used
Service discovery finished successfully
Process of obtaining install manifest initiated
Using the install manifest obtained via service discovery

 

solaris console login:

Automated Installation started
The progress of the Automated Installation will be output to the console
Detailed logging is in the logfile at /system/volatile/install_log

Press RETURN to get a login prompt at any time.

16:22:08    Using XML Manifest: /system/volatile/ai.xml
16:22:08    Using profile specification: /system/volatile/profile
16:22:08    Using service list file: /var/run/service_list
16:22:08    Starting installation.
16:22:08    0% Preparing for Installation
16:22:08    100% manifest-parser completed.
16:22:09    0% Preparing for Installation
16:22:09    1% Preparing for Installation
16:22:09    2% Preparing for Installation
16:22:09    3% Preparing for Installation
16:22:09    4% Preparing for Installation
16:22:24    7% target-discovery completed.
16:22:24    Selected Disk(s) : c2t0d0
16:22:24    13% target-selection completed.
16:22:24    17% ai-configuration completed.
16:22:24    19% var-share-dataset completed.
16:22:41    21% target-instantiation completed.
16:22:41    21% Beginning IPS transfer
16:22:41    Creating IPS image
16:22:45     Startup: Retrieving catalog 'solaris' ... Done
16:22:48     Startup: Caching catalogs ... Done
16:22:48     Startup: Refreshing catalog 'site' ... Done
16:22:48     Startup: Refreshing catalog 'solaris' ... Done
16:22:51     Startup: Caching catalogs ... Done
16:22:51    Installing packages from:
16:22:51        solaris
16:22:51            origin:  http://10.xx.xx.xxx:8000/
16:22:51        site
16:22:51            origin:  http://10.xx.xx.xxx:8001/
16:22:51     Startup: Refreshing catalog 'site' ... Done
16:22:52     Startup: Refreshing catalog 'solaris' ... Done
16:22:56    Planning: Solver setup ... Done
16:22:56    Planning: Running solver ... Done
16:22:56    Planning: Finding local manifests ... Done
16:22:56    Planning: Fetching manifests:   0/365  0% complete
16:23:03    Planning: Fetching manifests: 100/365  27% complete
16:23:08    Planning: Fetching manifests: 253/365  69% complete
16:23:16    Planning: Fetching manifests: 365/365  100% complete
16:23:25    Planning: Package planning ... Done
16:23:26    Planning: Merging actions ... Done
16:23:29    Planning: Checking for conflicting actions ... Done
16:23:31    Planning: Consolidating action changes ... Done
16:23:34    Planning: Evaluating mediators ... Done
16:23:37    Planning: Planning completed in 45.22 seconds
16:23:37    Please review the licenses for the following packages post-install:
16:23:37      runtime/java/jre-7                       (automatically accepted)
16:23:37      consolidation/osnet/osnet-incorporation  (automatically accepted,
16:23:37                                                not displayed)
16:23:37    Package licenses may be viewed using the command:
16:23:37      pkg info --license <pkg_fmri>
16:23:38    Download:     0/51156 items    0.0/831.8MB  0% complete
16:23:43    Download:   837/51156 items    5.4/831.8MB  0% complete (1.1M/s)

[…]

16:29:37    Download: 50159/51156 items  828.7/831.8MB  99% complete (714k/s)
16:29:42    Download: 50971/51156 items  831.1/831.8MB  99% complete (619k/s)
16:29:43    Download: Completed 831.78 MB in 365.45 seconds (2.3M/s)
16:29:55     Actions:     1/73904 actions (Installing new actions)
16:30:00     Actions: 15949/73904 actions (Installing new actions

[…]

16:34:51     Actions: 72496/73904 actions (Installing new actions)
16:34:56     Actions: 72687/73904 actions (Installing new actions)
16:35:01     Actions: Completed 73904 actions in 305.77 seconds.
16:35:02    Finalize: Updating package state database ...  Done
16:35:04    Finalize: Updating image state ...  Done
16:35:16    Finalize: Creating fast lookup database ...  Done
16:35:24    Version mismatch:
16:35:24    Installer build version: pkg://solaris/entire@0.5.11,5.11-0.175.1.0.0.24.2:20120919T190135Z
16:35:24    Target build version: pkg://solaris/entire@0.5.11,5.11-0.175.1.1.0.4.0:20121106T001344Z
16:35:24    23% generated-transfer-1181-1 completed.
16:35:25    25% initialize-smf completed.
16:35:25    Boot loader type SPARC ZFS Boot Block does not support the ...
16:35:25    Installing boot loader to devices: ['/dev/rdsk/c2t0d0s0']
16:35:26    Setting boot devices in firmware
16:35:26    Setting openprom boot-device
16:35:27    35% boot-configuration completed.
16:35:27    37% update-dump-adm completed.
16:35:27    40% setup-swap completed.
16:35:27    42% device-config completed.
16:35:28    44% apply-sysconfig completed.
16:35:29    46% transfer-zpool-cache completed.
16:35:38    87% boot-archive completed.
16:35:38    89% transfer-ai-files completed.
16:35:39    99% create-snapshot completed.
16:35:39    Automated Installation succeeded.
16:35:39    System will be rebooted now

Automated Installation finished successfully
Auto reboot enabled. The system will be rebooted now
Log files will be available in /var/log/install/ after reboot
Dec 17 16:35:43 solaris reboot: initiated by root
Dec 17 16:35:50 solaris syslogd: going down on signal 15
syncing file systems... done
rebooting...

 

La configuration d'un serveur AI et la personnalisation d'un client (manifest et profile) sont des étapes assez simple à mettre en place. Il est grand temps maintenant, pour vous, de mettre en place votre architecture d'installation pour Solaris 11.

 

Par gloumps - Publié dans : administration
Ecrire un commentaire - Voir les 0 commentaires

Vendredi 1 février 2013 5 01 /02 /Fév /2013 23:25

 

Cela fait déjà un petit moment que j'ai écrit la 1er partie de cet article et j'imagine que vous aviez hâte dans connaître le dénouement ?

 

Pour rappel, la forte consommation CPU (notamment le temps system) provenait de l'agent Grid d'Oracle. Suite à la modification dans le kernel du mode d'allocation des pages (pg_contig_disable), la charge CPU semblait se répartir plus équitablement entre le temps system et le temps user. Mais... quelque chose me choquait encore...

 

# vmstat 5
kthr      memory            page            disk          faults      cpu
r b w   swap  free  re  mf pi po fr de sr m1 m1 s0 s1   in   sy   cs us sy id
10 0 0 10703368 22253264 686 5492 144 0 0 0 0 25 4 4 4 14772 115284 20499 46 28 26
6 0 0 25164544 7403960 1041 8609 0 0 0 0 0 1  0  0  0 13946 131868 24255 45 52 3
5 0 0 25236360 7412640 892 7452 0 0 0 0 0  1  0  0  0 17576 142221 28069 47 44 9
0 0 0 25265688 7406912 960 8391 0 0 0 0 0  1  0  0  0 17918 151723 29192 46 45 8
0 0 0 25273088 7403816 1053 9120 0 0 0 0 0 1  0  6  6 17035 189702 29475 47 45 8
1 0 0 25212800 7387888 861 7344 0 0 0 0 0  1  0  0  0 17021 148306 27156 48 46 6
1 0 0 25269080 7405256 996 8419 0 0 0 0 0  1  0  0  0 17066 143782 27059 45 44 12

 

La répartition du temps system et du temps user est bien égale. Ce qui me semble surprenant c'est d'avoir un temps system aussi important pour ce type d'application : exécution de bases Oracle. Du temps system pour des bases de données, je veux comprendre pourquoi.  

 

# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
[…]
  unix`page_lookup_create               463
  unix`bzero                            509
  unix`utl0                             510
  unix`mutex_exit                       693
  genunix`avl_walk                      843
  FJSV,SPARC64-VI`cpu_halt_cpu         1243
  unix`page_exists                     2782
  unix`mutex_delay_default             2887
  unix`page_trylock                    3086
  FJSV,SPARC64-VI`copyout_more         3455
  unix`mutex_enter                     5212

 

Encore des mutex !! Toujours des mutex !? Si vous avez bien suivie la 1er partie de cette analyse, après l'agent Grid, le deuxième contributeur des muxtex était Oracle. Mais vérifions tout de même.

 

# dtrace -n 'lockstat::mutex_enter: { @[execname] = count(); }'
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
^C
[…]
  emdctl                    15109
  init                      19896
  dtrace                    21512
  sldrm_hist                61435
  zpool-zone039             85352
  sched                    236548
  sldrm_coll               508763
  perl                     697386
  fsflush                 1168071
  emagent                 1590809
  tnslsnr                 2150743
  oracle                 10154578

 

Regardons dans le détail la ressource utilisée pour ce type de mutex.

 

# dtrace -n 'lockstat::mutex_enter: /execname == "oracle"/ \
{ @[stack()] = count(); } tick-60s { trunc(@,5); exit(0); }'

dtrace: description 'lockstat::mutex_enter: ' matched 4 probes
CPU     ID                    FUNCTION:NAME
  3  65327                        :tick-60s

 […]

          unix`page_trylock+0x38
          unix`page_trylock_cons+0xc
          unix`page_get_mnode_freelist+0x19c
          unix`page_get_freelist+0x430
          unix`page_create_va+0x258
          genunix`swap_getapage+0x168
          genunix`swap_getpage+0x4c
          genunix`fop_getpage+0x44
          genunix`anon_private+0x140
          genunix`segvn_faultpage+0x808 
          genunix`segvn_fault+0xbf0

          genunix`as_fault+0x4c8
          unix`pagefault+0xac
          unix`trap+0xd50         
          unix`utl0+0x4c

       3818149

 

          unix`page_trylock+0x38
          unix`page_trylock_cons+0xc
          unix`page_get_mnode_freelist+0x19c
          unix`page_get_freelist+0x430
          unix`page_create_va+0x258
          genunix`swap_getapage+0x168
          genunix`swap_getpage+0x4c
          genunix`fop_getpage+0x44
          genunix`anon_zero+0x88
          genunix`segvn_faultpage+0x1e0
          genunix`segvn_fault+0xbf0
          genunix`as_fault+0x4c8
          unix`pagefault+0xac
          unix`trap+0xd50
          unix`utl0+0x4c
      26458018

 

Ce résultat est vraiment intéressant : mon temps system (induit par des mutex) est consécutif à des pagefault. Oracle effectue des opérations ZFOD (anon_zero) pour allouer de nouvelles pages type anonymous memory (l'info en plus : le backing store des pages anonymous memory est le swap space - explications des opérations types swap_getpage).

 

Le serveur dispose de plusieurs zones qui exécutent plusieurs bases de données Oracle. Le problème est'il localisé à une zone, une base ? Ou bien une problème générale sur le serveur ? Vérifions cela. 

 

# dtrace -n '::anon_zero:entry /execname == "oracle"/ \
{ @[zonename] = count(); }'                                     
dtrace: description '::anon_zero:entry ' matched 1 probe
^C 

  global                 1004
  zone013                2775
  zone015                3266
  zone034                7206
  zone043               16857
  zone039              319582

 

# dtrace -n '::anon_zero:entry /zonename == "zone039" \
&& execname == "oracle"/
{ @[pid] = count(); }'
dtrace: description '::anon_zero:entry ' matched 1 probe
^C
[…]

     4387              599
     3903              815
    29484              930
    17591              991
    13001             3763
    18422             6550

 

Deux PID semblent sortir du lot lors de ma prise de mesures.

 

# ptree 18422
18422 oracleXXXX1 (LOCAL=NO)

# ptree 13001
13001 oracleXXXX1 (LOCAL=NO)

 

Pour résumé, mes mutex proviennent d'allocation ZFOD effectuée par des sessions Oracle à une base spécifique. On se rapproche de la conclusion. Mais avant essayons dans savoir plus en affichant ce qui se passe en temps user pour un des process trouvé.

 

# dtrace -n '::anon_zero:entry /pid == 18422/ \
{ @[ustack()] = count(); } tick-30s { trunc(@,5); exit(0); }'
dtrace: description '::anon_zero:entry ' matched 2 probes
CPU     ID                    FUNCTION:NAME
11  65327                        :tick-30s


         libc_psr.so.1`memset+0x140
         oracle`klmalf+0x3c
         oracle`kllcqas+0xb8
         oracle`kcblasm+0x48
         oracle`kxhfNewBuffer+0x270
         oracle`qerhjSplitBuild+0x250
         oracle`qerixtFetch+0x558
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qervwFetch+0x94
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`opifch2+0x28f4
         oracle`opiall0+0x884
         oracle`opial7+0x390
         oracle`opiodr+0x590
         oracle`ttcpip+0x420
        1200


         oracle`qerhjBuildHashTable+0x784
         oracle`qerhjInnerProbeHashTable+0x250
         oracle`qerixtFetch+0x558
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x1c8
         oracle`qervwFetch+0x94
         oracle`rwsfcd+0x6c
         oracle`qerhjFetch+0x530
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`qerjotFetch+0x1f0
         oracle`opifch2+0x28f4
         oracle`opiall0+0x884
         oracle`opial7+0x390
         oracle`opiodr+0x590
         oracle`ttcpip+0x420
         oracle`opitsk+0x5e8
         oracle`opiino+0x3e8
         oracle`opiodr+0x590
         oracle`opidrv+0x448
        1405
 

          libc_psr.so.1`memset+0x140
          oracle`klmalf+0x3c
          oracle`kllcqas+0xb8
          oracle`kcblasm+0x48
          oracle`kxhfNewBuffer+0x270
          oracle`qerhjGetNewBuffer+0x24
          oracle`ksxb1bqb+0xa0
          oracle`kxhrPack+0x564
          oracle`qerhjSplitBuild+0x164
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
         2400

 

          libc_psr.so.1`memset+0x140
          oracle`qerhjBuildHashTable+0x228
          oracle`qerhjInnerProbeHashTable+0x250
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x1c8
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
          oracle`opial7+0x390
          oracle`opiodr+0x590
          oracle`ttcpip+0x420
          oracle`opitsk+0x5e8
          oracle`opiino+0x3e8
          oracle`opiodr+0x590
         5110

 

          libc_psr.so.1`memset+0x140
          oracle`klmalf+0x3c
          oracle`kllcqas+0xb8
          oracle`kcblasm+0x48
          oracle`kxhfNewBuffer+0x270
          oracle`qerhjGetNewBuffer+0x24
          oracle`ksxb1bqb+0xa0
          oracle`kxhrPack+0x534
          oracle`qerhjSplitBuild+0x164
          oracle`qerixtFetch+0x558
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qervwFetch+0x94
          oracle`rwsfcd+0x6c
          oracle`qerhjFetch+0x530
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`qerjotFetch+0x1f0
          oracle`opifch2+0x28f4
          oracle`opiall0+0x884
         6000

 

Je suis loin d’être spécialiste Oracle DB, mais d’après les ustack il s’agit d’une "hash join" (kxhf*). La zone mémoire utilisée pour ce genre d’opérations est normalement la zone SQL Work Areas (sous-ensemble de la PGA). Deux pistes sont donc à vérifier : n’y a-t-il pas un problème avec la requête SQL (pb de jointure ?) ou bien n’y a-t-il pas un problème de dimensionnement de la PGA ?

 

Un petit passage par l’équipe DBA Oracle s’impose…

 

Epilogue : en recherchant dans l’historique du monitoring, le problème de l’agent Grid provenait aussi de cette base. Bizarre non !? Comme l'a souligné Eric G. dans son commentaire sur la 1er partie, si un élément de surveillance (ici l'agent Grid) pose problème, il doit y avoir un autre problème. Pour cette fois c'est exact...

 

Par gloumps - Publié dans : kernel
Ecrire un commentaire - Voir les 0 commentaires

Présentation

Informations personnelles

  • Passionné d'informatique, je travaille actuellement comme expert système Solaris. Vous trouverez plus de renseignements à mon sujet sur mon profil Linkedin.

Flux RSS

  • Flux RSS des articles

Recherche

Calendrier

Avril 2014
L M M J V S D
  1 2 3 4 5 6
7 8 9 10 11 12 13
14 15 16 17 18 19 20
21 22 23 24 25 26 27
28 29 30        
<< < > >>
Créer un blog gratuit sur over-blog.com - Contact - C.G.U. - Signaler un abus - Articles les plus commentés