kernel


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

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

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

Mardi 20 novembre 2012 2 20 /11 /Nov /2012 22:06

 

Première partie d'une analyse effectuée sur un système Solaris 10 exécutant plusieurs bases de données Oracle. Les symptômes remontés par l'équipe DBA sont les suivants : temps de réponse long sur plusieurs bases. 

 

Un petit vmstat rapide, pour connaitre grossièrement l’utilisation du serveur.

 

# vmstat 5 100
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
9 0 0 10677368 22372512 680 5482 106 0 0 0 0 25 4 4 4 14735 114426 20380 46 27 27
[…]
23 0 0 9135032 22314120 4792 21638 0 0 0 0 0 1 0 0  0 11118 154028 16758 50 50 0
16 0 0 9137544 22315040 5294 23490 0 0 0 0 0 1 0 0  0 11380 153204 18659 48 52 0
17 0 0 9084960 22258160 2177 10563 0 0 0 0 0 1 0 10 10 9922 137140 14022 43 54 3
24 0 0 9179648 22320080 3362 15628 0 0 0 0 0 1 0 0  0 10750 128918 16896 43 57 0
30 0 0 8850312 22046056 288 2054 0 0 0 0 0 1  0  0  0 10807 99560 14018 31 63 6
126 0 0 8853432 22082880 41 616 0 0 0 0 0  1  0  6  6 5752 31932 6774 10 88 2
661 0 0 8923392 22133776 19 197 0 0 0 0 0  0  0  0  0 2263 5386 1704  3 97  0
465 0 0 8991776 22117088 25 287 0 0 0 0 0  1  0  3  3 2453 8860 2140  4 96  0
46 0 0 8953016 22085792 223 1502 0 0 0 0 0 1  0  0  0 5766 38776 7626 13 86 1
63 0 0 8920736 22079448 109 846 0 0 0 0 0  1  0  0  0 6630 52695 9918 15 83 2
67 0 0 9076624 22190944 1054 7254 0 0 0 0 0 1 0  4 20 5746 97461 7816 33 66 0
53 0 0 8993152 22164344 815 6238 0 0 0 0 0 2  0 176 173 7381 138464 13787 34 66 0
154 0 0 8815312 22116736 37 745 0 0 0 0 0  1  0  0  0 5150 54699 8493 15 85 0
168 0 0 8628120 22079000 22 399 0 0 0 0 0  1  0  0  0 3899 23637 5677 8 92  0
355 0 0 8558232 22016008 23 431 0 0 0 0 0  1  0  4  4 3364 14270 3970 6 94  0
130 0 0 8944384 22119872 949 6035 0 0 0 0 0 1 0  0  0 5608 64746 5932 23 77 0
94 0 0 8696336 22046504 73 782 0 0 0 0  0  1  0  4  4 5918 39593 6905 11 89 0
127 0 0 8570488 21995968 53 560 0 0 0 0 0  1  0  0  0 5745 26933 6982 9 91  0
75 0 0 8915344 22101408 531 4554 0 0 0 0 0 1  0  4  4 6366 81465 9546 23 77 0
26 0 0 8900360 22049976 86 1279 0 0 0 0 0  1  0  0  0 8994 95004 14896 28 71 1
36 0 0 8860368 22037360 184 1635 0 0 0 0 0 1  0  0  0 7535 89424 13136 23 77 0
49 0 0 8820896 22127776 22 1026 0 0 0 0 0  1  0  5  5 10203 71434 12679 22 73 5
427 0 0 8719360 22085440 13 157 0 0 0 0 0  1  0 227 205 3164 8480 2555 4 96 0
487 0 0 8812896 22104528 77 717 0 0 0 0 0  1  0  0  0 2769 9668 2381  5 95  0
42 0 0 9051608 22152568 588 4325 0 0 0 0 0 1  0  0  0 7835 82729 11531 30 69 1
151 0 0 9023256 22246008 188 2021 0 0 0 0 0 1 0  4  4 5405 40646 9076 14 86 0
[..]

 

Deux remarques vis-à-vis de ce résultat : d’une part la run queue globale est complètement saturée, d’autre part la répartition user/system est de 1 pour 3. Qu’une utilisation system soit supérieur à une utilisation user ne me choque pas forcément, tout dépend des applications, cependant dans mon cas (bases de données Oracle), ce ratio ne me plait pas.

 

Voyons voir qui utilise tout ce temps kernel.

 

# dtrace -n 'profile-997hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-1001hz ' matched 1 probe
^C 
[…]
  pgrep                               156
  nmupm                               164
  dtrace                              166
  emdctl                              195
  check_bnp_proces                    225
  tnslsnr                             638
  fsflush                             846
  sldrm_coll                         1182
  perl                               7639
  sched                              9911
  oracle                            17735
  emagent                           26944

 

Intéressant, le temps system est utilisé majoritairement par l’agent Grid d’Oracle (emagent). Détaillons d’un peu plus près les fonctions du kernel sollicitées.

 

# dtrace -n 'profile-997hz /arg0/ { @[func(arg0)] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C 
[…]
  unix`bzero                                437
  unix`_resume_from_idle                    446
  genunix`mstate_aggr_state                 448
  genunix`avl_walk                          502
  FJSV,SPARC64-VI`cpu_smt_pause             549
  unix`page_lookup_create                   625
  unix`mutex_exit                           870
  unix`utl0                                 877
  FJSV,SPARC64-VI`cpu_halt_cpu             1311
  unix`page_exists                         1765
  unix`mutex_delay_default                 2801
  FJSV,SPARC64-VI`copyout_more             2934
  unix`page_trylock                        3246
  unix`mutex_enter                         5078

 

Le temps kernel est utilisé principalement à la gestion de lock (mutex). Existe t'il une relation entre ces locks et l’agent Grid ?

 

# dtrace –n ‘lockstat::mutex_enter: { @[execname] = count(); }’
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
^C
[…]
  dtrace                    34218
  sh                        66256
  fsflush                   104986
  sldrm_hist                186238
  nmupm                     294968
  emdctl                    791171
  sched                     861038
  sldrm_coll               1250578
  tnslsnr                  2617337
  perl                     3111793
  oracle                  13825389
  emagent                 15498584

 

A priori oui, il existe une relation entre la forte utilisation kernel (mutex) et l'agent Grid (mais pas seulement). Analysons d’un peu plus près la stack de l'agent Grid au moment des locks.

 

# dtrace –n ‘lockstat::mutex_enter: /execname == “emagent”/ { @[stack()] = count() } \
tick-60s { trunc(@,5); exit(0); }’
dtrace: description 'lockstat::mutex_enter: ' matched 3 probes
[…]
              unix`page_trylock+0x38
              unix`page_trylock_cons+0xc
              unix`page_get_mnode_freelist+0x19c
              unix`page_get_replacement_page+0x30c
              unix`page_claim_contig_pages+0x178
              unix`page_geti_contig_pages+0x618
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0x910
              unix`ktl0+0x48
              genunix`poll_common+0x5c8
              genunix`pollsys+0xf8
              unix`syscall_trap32+0xcc
           114469

              unix`page_trylock+0x38
              unix`page_trylock_contig_pages+0x94
              unix`page_geti_contig_pages+0x5f4
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
           125499 

              unix`page_trylock+0x38
              unix`page_trylock_cons+0xc
              unix`page_get_mnode_freelist+0x19c
              unix`page_get_replacement_page+0x30c
              unix`page_claim_contig_pages+0x178
              unix`page_geti_contig_pages+0x618
              unix`page_get_contig_pages+0x160
              unix`page_get_freelist+0x430
              unix`page_alloc_pages+0x110
              genunix`anon_map_privatepages+0xa4
              genunix`anon_map_getpages+0xad0
              genunix`segvn_fault_anonpages+0x32c
              genunix`segvn_fault+0x530
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
         17880348

 

En observant rapidement le résultat, on constaque que les locks proviennent d’allocation de pages mémoire !? Si on regarde un peu plus dans le détail, on constate quelque chose d’intéressant : le système tente d’allouer des pages mémoire de manières contiguës (fonction page_get_contig_pages). Il s’agit « normalement » d’une optimisation du système Solaris (évite la fragmentation mémoire, impact sur les mécanismes de translation d'adresses). Dans notre cas, cela semble pénaliser le fonctionnement du système.

 

Une petite explication du Support Oracle Solaris sur ce sujet.

 

The "Large Page Out Of the Box" (LPOOB) feature of the Oracle Solaris 10 memory management, first implemented in Oracle Solaris 10 1/06 (Update 1), can lead to performance problems when the system runs out of large chunks of free contiguous memory. This is because the Oracle Solaris 10 kernel by default will attempt to relocate memory pages to free up space for creating larger blocks of contiguous memory. Known symptoms are high %system CPU time in vmstat, high number of cross calls in mpstat, and Oracle calling mmap(2) to /dev/zero for getting more memory.

 

Il est possible de changer ce type de fonctionnement par défaut (on alloue des pages sans ce soucier de l’emplacement contiguës de celles-ci) en modifiant le paramètre kernel pg_contig_disable. Petite remarque : ce paramètre influence uniquement la mémoire PGA de la base de données Oracle (pas d'influence sur la mémoire SGA).

 

Testons rapidement la modification de ce paramètre sur notre système.

 

# mdb –kw
Loading modules: [ unix genunix specfs dtrace zfs sd mpt px ssd fcp fctl qlc mpt_sas ip hook neti sctp arp usba md cpc random crypto fcip logindmux ptm ufs sppp nfs lofs ipc ]
> pg_contig_disable/X
pg_contig_disable:
pg_contig_disable:              0              
> pg_contig_disable/W 1
pg_contig_disable:              0               =       0x1
> pg_contig_disable/X
pg_contig_disable:
pg_contig_disable:              1
> ::exit

 

# vmstat 5 30
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 10645464 22354816 680 5481 104 0 0 0 0 25 4 4 4 14733 114929 20416 46 27 27
8 0 0 8071552 21199136 865 6976 0 0 0 0 0  1  0  0  0 14630 138815 26507 54 45 1
13 0 0 7960624 21162752 898 6521 0 0 0 0 0 1  0  0  0 12945 115064 23913 46 54 0
6 0 0 8017848 21150384 657 6674 0 0 0 0 0  1  0  0  0 14140 128303 25855 54 45 0
8 0 0 7965472 21129192 704 6301 0 0 0 0 0  1  0  7  7 15013 130409 25934 55 44 1
39 0 0 7908096 21067600 678 6408 0 0 0 0 0 1  0  0  0 14324 113376 26509 46 54 0
11 0 0 7936560 21059424 717 6684 0 0 0 0 0 1  0  0  0 13445 124844 23464 52 47 1
4 0 0 7860976 20987424 880 6478 0 0 0 0 0  1  0  0  0 14499 129461 26395 53 46 0
13 0 0 7881128 21004464 660 6154 0 0 0 0 0 2  0  0  0 15000 124875 25740 50 48 2
5 0 0 7824424 20954160 709 5939 0 0 0 0 0  1  0  0  0 14831 138457 28836 54 45 1
9 0 0 7774880 20924240 1080 8938 0 0 0 0 0 1  0  5  5 13451 126547 24567 50 49 0
[…]

 

D'une part, la run queue globale est beaucoup moins saturée et, d'autre part, la répartition user/system semble s'être équilibrée. Reste à savoir si la consomation system provient toujours de l'agent Grid ?

 

# dtrace -n 'profile-997hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-997hz ' matched 1 probe
^C
[…]
  nmupm                        439
  init                         541
  perl                        1158
  fsflush                     1165
  collectd                    1679
  sldrm_coll                  2630
  emagent                     4264
  tnslsnr                    10857
  sched                      13906
  oracle                    105798

 

La modification du paramètre pg_config_disable semble améliorer le fonctionnement du serveur. L'agent Grid utilise beaucoup moins les ressources system (une bonne chose). Les temps de réponses sont meilleurs mais... Mais voilà : le temps system reste anormalement élevé pour un serveur hébergeant des bases Oracles.

 

Suite de l'analyse lors d'un prochain article.

 

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

Samedi 16 juin 2012 6 16 /06 /Juin /2012 10:16

 

 

Petit compte rendu sur un problème de performance que je viens de rencontrer sur un serveur Solaris Sparc avec une base de donnée Oracle.  Le contexte étant le suivant : temps de réponse dégradés suite au reboot du serveur. Bien entendu, aucun changement entre les deux reboot et pourtant l'application fonctionne moins bien qu'avant.

 

Commençons par le début :

 

$ vmstat 1 60

 kthr      memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr s7 s8 s9 s1   in   sy   cs us sy id
 2 2 0 153281392 104614544 4824 7797 16312 457 457 0 0 6 2 0 0 12173 125078 25167 18 9 73
 4 1 0 110702776 64484544 8681 26172 36014 0 0 0 0 0 0 0 0 28270 284267 39452 51 45 4
 27 2 0 110701000 64466128 8187 25244 33717 0 0 0 0 0 0 0 0 30699 317983 40125 56 43 0
 58 4 0 110655752 64437344 6890 35606 35200 0 0 0 0 0 0 0 0 29945 270086 39936 51 46 4
 81 2 0 110652760 64419824 2422 4687 21878 0 0 0 0 0 0 0 0 19933 146223 21668 56 42 2
 68 1 0 110640232 64442472 3117 7019 36429 0 0 0 0 0 0 0 0 17947 153021 21306 56 40 4
 82 2 0 110673872 64459640 3740 19469 15517 0 0 0 0 0 0 0 0 17143 197402 23112 55 45 0
 53 1 0 110817840 64541056 16751 85478 37213 0 0 0 0 13 0 0 0 32290 400389 43440 50 49 2
 27 1 0 110804904 64526728 9514 25054 29034 0 0 0 0 24 24 24 24 32222 362887 43524 57 41 2
 22 3 0 110760264 64497288 8110 10600 27836 0 0 0 0 10 24 24 24 33012 368583 46368 54 42 4
 46 1 0 110219560 64480488 5238 9330 16615 0 0 0 0 24 24 24 24 33111 293475 41391 54 45 1
 31 2 0 109691888 64462816 6337 5855 35649 0 0 0 0 24 24 24 24 32564 324041 41930 51 47 3
 8 1 0 110828328 64515976 7183 15999 60116 7 0 0 0 24 24 24 24 30930 363314 48875 55 37 8
 4 3 0 110738808 64452664 4294 4912 33406 0 0 0 0 24 24 24 24 25878 284752 40035 49 43 9

[...]

 

La runqueue est quelque peu remplie, vous ne trouvez pas ? Normalement l'utilisation système de ce serveur avoisine les 15%. Actuellement nous consommons plus du double. Bizarre !?

 

En détaillant un peu plus l'utilisation par cpu, j'obient cela :

 

$ mpstat 1 60

CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
  0  130   2 3928   219    8   16   18    5  152    0    68   36  64   0   0
  1   52  17 668688   152   17  514   84  102  119    0  2700   19  78   0   3
  2  123  23 875479    80   11  190   41   37  273    0   835   20  78   0   2
  3   67  10 5639   186   19  596  108  171 2739    2  4200   45  50   0   5
  4   82   0 2238   359   10  715  278  131  315    0  4078   47  52   0   1
  5  106   0 3470   191   16  325  120   91  170    1  1498   46  53   0   1
  6   81   0 6341   893   24 2110  739  410  174    0 10915   72  25   0   2
  7   48   2 4116   198   16  378  103   90  139    0  1809   20  78   0   2
  8   30   0 1686   103   18  776   40  128 2272    0  6072   70  20   0  10
  9   77   1 2085   106   22  486   32  110 4239    1  5263   35  48   0  17
 10   57   1  830   119   25 1760   41  111 1146    1 11804   56  33   0  11
 11   50   0 39677   142   40  602   35  125   93    0  3952   67  15   0  18
 12   82   0 3574   156   15  607   72  143  298    1  3154   36  49   0  15
 13  118   0 1263    96   25  174   37   60  251    0  1072   47  49   0   4
 14   66   0  992   146   16  600   57  125   75    0  3470   66  12   0  22
 15   53   0  330    87   11  448   12   38   96    0  2328   30  57   0  12
 16   57   4 7363   318   36 1543  147  431  124    0  7300   52  24   0  25
 17   38   2 10889 10088 9791 1366  142  389  306    0  5889   20  59   0  20
 18   61   2 4960   251   33 1051  115  327  119    0  5081   49  32   0  20
 19   20   1 4050   235   22 1149  110  281  153    0  5047   28  49   0  23
 20   69   0 189652   226   22  579  131  155  224    0  3525   32  61   0   6
 21   12   1 1361611    57   16   27    4   13   96    0   131    4  95   0   1
 22   88   1 5381   423   38 1049  259  285  601    0  6239   60  30   0  10
 23  144   1 5722   374   40  899  223  246 2358    2  6196   41  50   0   8
512   33   2 17331    65   10  102   22   31  499    0   923   12  86   0   2
513   33  19 120216   279   22  717  143  170  106    0  3107   43  55   0   2
514   53  20 14957   582   29 2035  398  480  215    1  9802   46  43   0  11
515    5  13 2871  1303 1218  139   24   32 2545    0   952    6  93   0   1
516   57   0 4672   243   14  475  175  110  170    0  2339   42  57   0   1
517   83   0 2163  1314 1250   23    5    3   84    0    86   25  75   0   0
518  106   1 8336  1001   25 2445  863  415  231    2 11656   65  32   0   3
519   56   0 5720   819   25 1905  655  415  229    1  9969   61  38   0   2
520   45   0 3534   139   36  411   28  141  139    0  1675   43  28   0  29
521   27   2 4369   167   37  677   27  149  184    0  2423   31  24   0  45
522   49   0 2994   128   27  644   20  114  143    0  2822   44  20   0  36
523   52   0 5220   176   27  819   56  151 2977    1  6423   25  38   0  37
524  172   1  310    55    8  304   10   27  233    0  1564   55  32   0  13
525   73   2 1535   123   13  597   46  115   86    0  3898   64  22   0  14
526   77   1 3821   242   29 1059   94  225  202    0  5572   50  28   0  22
527   52   1 2318   234   25 1106   87  234 1026    0  4908   39  25   0  36
528   59   0 4609   248   33 1145   98  285  164    0  5014   38  36   0  26
529   25   0 11442   341   41 1818  149  454   97    0  8854   37  31   0  32
530   33   0  553    81   10    4    5    1   48    0     0   34  66   0   0
531   51   1 6084   393   50 1754  172  468  113    0  7707   43  21   0  36
532   30   0 700781   139   12  263   85   65  135    0  1747   30  68   0   2
533   59   2 368218   183   29  394   73   95  252    0  2593   31  65   0   4
534  250   2 150619   255   32  685  145  228 2420    1  3932   39  59   0   2
535  108   4 906001   134   20  360   59  104  215    0  1804   24  72   0   4

[...]

 

Le nombre de smtx est anormalement haut. Regardons avec Dtrace ce qui se passe en mode kernel :

 

# ./hotkernel

Sampling... Hit Ctrl-C to end.
^C

FUNCTION                        COUNT   PCNT
genunix`rctl_set_tearoff            1   0.0%
[...]

unix`idle                        6622   2.8%
SUNW,UltraSPARC-IV              15472   6.6%
unix`default_lock_delay         18426   7.8%
unix`disp_getwork               44618  19.0%
unix`mutex_delay_default       115315  49.0%

 

Voilà pourquoi le nombre de smtx est élevé. Le temps d'utilisation kernel provient essentiellement de mutex. Voyons qui les génèrent :

 

# dtrace -n 'profile:::profile-1001hz /arg0/ { @[func(arg0), execname] = count(); }'

[...]

  SUNW,UltraSPARC-IV+`gettick      oracle            5062
  unix`mutex_enter                 oracle            6222
  unix`mutex_delay_default         svc.startd        6768
  unix`kcage_cageout               pageout           8347
  unix`mutex_delay_default         tnslsnr           8811
  unix`page_numtopp_nolock         pageout           9325
  unix`generic_idle_cpu            sched             9829
  unix`idle                        sched            76849
  unix`default_lock_delay          oracle           96305
  unix`disp_getwork                sched           275834
  unix`mutex_delay_default         oracle          573610

 

Il s'agit des process Oracle. L'analyse de la stack() peut nous en dire un peu plus :

 

# dtrace -n 'profile:::profile-1001hz /arg0 && execname == "oracle"/ \
{ @[stack()] = count(); } tick-60s { trunc(@,10); exit(0); }'
 

dtrace: description 'profile:::profile-1001hz ' matched 2 probes
CPU     ID                    FUNCTION:NAME
 16  85099                        :tick-60s

[...]
              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tlb_range_demap+0x88
              unix`hat_unload_callback+0x7dc
              genunix`segvn_unmap+0x28c
              genunix`as_unmap+0xf0
              genunix`munmap+0x78
              unix`syscall_trap+0xac
             5736
[...]
              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_do_memload+0xf4
              genunix`segvn_faultpage+0x560
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
             7342

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_unload_callback+0x898
              genunix`segvn_unmap+0x28c
              genunix`as_unmap+0xf0
              mm`mmsegmap+0xa8
              genunix`cdev_segmap+0x60
              specfs`spec_char_map+0x104
              specfs`spec_map+0x94
              genunix`fop_map+0x40
              genunix`smmap_common+0x3ac
              genunix`smmap64+0x80
              unix`syscall_trap+0xac
             8367

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tlb_range_demap+0x88
              unix`hat_unload_callback+0x7dc
              genunix`anon_private+0x20c
              genunix`segvn_faultpage+0x7d4
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
            12659

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_size_tsb+0x4
              unix`sfmmu_check_page_sizes+0x17c
              unix`hat_do_memload+0xf4
              genunix`segvn_faultpage+0x32c
              genunix`segvn_fault+0xbf0
              genunix`as_fault+0x4c8
              unix`pagefault+0xac
              unix`trap+0xd50
              unix`utl0+0x4c
            27669

              unix`mutex_delay_default+0x4
              unix`current_thread+0x164
              unix`default_lock_delay+0x6c
              unix`mutex_vector_enter+0x460
              unix`sfmmu_hat_enter+0x2c
              unix`sfmmu_tsbmiss_exception+0x6c
              unix`utl0+0x4c
            98775

 

Un des avantages de l'ISM est de diminuer l'impact sur les tables TLB/TSB. Au vu des appels, il semble que cela soit le contraire. L'appel à la fonctions sfmmu_check_page_sizes() est assez étrange : normalement un segment ISM utilise des larges de 4Mo sur Sparc. Alors pourquoi rechercher une taille de page ?

 

En parcourant le code source d'Opensolaris pour la fonction sfmmu_tsbmiss_exception() on peut lire cela :

 

/*
* Handle exceptions for low level tsb_handler.
*
* There are many scenarios that could land us here:
*
* If the context is invalid we land here. The context can be invalid
* for 3 reasons: 1) we couldn't allocate a new context and now need to
* perform a wrap around operation in order to allocate a new context.
* 2) Context was invalidated to change pagesize programming 3) ISMs or
* TSBs configuration is changeing for this process and we are forced into
* here to do a syncronization operation. If the context is valid we can
* be here from window trap hanlder. In this case just call trap to handle
* the fault.
*
[...]

 

Le cas 3 est assez surprenant : un changement de configuration ISM pour un process donné ? Vérifions un peu le mapping mémoire du segment ISM :

 

# pmap -xs 5514 | more

5514:   ora_pmon_XXXX01
         Address   Kbytes     RSS   Anon   Locked Pgsz Mode   Mapped File
0000000100000000    73728   73728      -        -   4M r-x--  oracle
0000000104800000     8192    8192      -        -    - r-x--  oracle
0000000105000000    20480   20480      -        -   4M r-x--  oracle
[...]

0000000380000000     8192    8192      -     8192   4M rwxsR  [ ism shmid=0x3 ]
0000000380800000    16384   16384      -    16384    - rwxsR  [ ism shmid=0x3 ]
0000000381800000    16384   16384      -    16384   4M rwxsR  [ ism shmid=0x3 ]
0000000382800000     4096    4096      -     4096    - rwxsR  [ ism shmid=0x3 ]
0000000382C00000    20480   20480      -    20480   4M rwxsR  [ ism shmid=0x3 ]
0000000384000000     4096    4096      -     4096   8K rwxsR  [ ism shmid=0x3 ]
0000000384400000    36864   36864      -    36864   4M rwxsR  [ ism shmid=0x3 ]
0000000386800000       16      16      -       16    - rwxsR  [ ism shmid=0x3 ]
0000000386804000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]
0000000386806000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
0000000386808000       24      24      -       24   8K rwxsR  [ ism shmid=0x3 ]
000000038680E000       32      32      -       32    - rwxsR  [ ism shmid=0x3 ]
0000000386816000       16      16      -       16   8K rwxsR  [ ism shmid=0x3 ]
000000038681A000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
[...]
000000038683A000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]
000000038683C000       24      24      -       24    - rwxsR  [ ism shmid=0x3 ]
0000000386842000       16      16      -       16   8K rwxsR  [ ism shmid=0x3 ]
0000000386846000        8       8      -        8    - rwxsR  [ ism shmid=0x3 ]
0000000386848000        8       8      -        8   8K rwxsR  [ ism shmid=0x3 ]

[...]

 

Quelque chose cloche !! Pour le même segment ISM nous avons une multitude de pages de tailles différentes mais surtout l'allocation du segment ISM est complètement fragmentée. Les sessions Oracle perdent un temps important dans la gestion de mémoire ISM. L'origne reste cependant inconnu !

 

L'ouverture d'un call au support Oracle confirme bien cette analyse (merci Alain). Cependant rien de bien précis concernant l'origine. Lors d'une activitée mémoire soutenue sur un serveur, ce bug peut se produire mais dans notre cas le serveur venait de rebooter. S'agissant d'une base Oracle 10.2.0.4, l'option NUMA est activée. Du coup le segment ISM est découpé entre les différents lgrp disponibles sur le serveur. La recherche de page par sous segment ISM lors de l'activation du NUMA peut poser un peu plus de problème (cela fonctionnait avant non ?). La taille de l'ARC peut aussi influencer lors de la recherche des pages pour la création de l'ISM. Mystère...

 

 

Ci-joint quelques références sur ce sujet :

 

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

Août 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 31
             
<< < > >>
Créer un blog gratuit sur over-blog.com - Contact - C.G.U. - Signaler un abus - Articles les plus commentés