kernel - Solaris mon amour

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

SVM hang due to error disk (analyze)

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.

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

23 février 2013 6 23 /02 /février /2013 21:37

Observation : fastresync et ACFS

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.

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

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

Observations : analyse d'un core "...Unable to fork..."

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...

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

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

Consommation CPU & Gestion mémoire (2ème partie)

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...

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

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

Consommation CPU & Gestion mémoire (1er partie)

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.

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

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

Fragmentation de l'Intimate Shared Memory (ISM)

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 :

Chapitre 12 "Hardware Address Translation" dans Solaris Internals
Chapitre 16 "Support for NUMA and CMT Hardware" dans Solaris internals
Architecture NUMA dans Solaris (10 et 11)
ISM sous Solaris 10x86 (Partie 1, Partie 2 et Workarounds)
Optimizing Applications with Large Working Sets in Solaris 8 and 9
Opensolaris code : hat_sfmmu.c
Opensolaris code : hat.h

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

15 mars 2012 4 15 /03 /mars /2012 17:32

Architecture NUMA dans Solaris (10 et 11)

Lors des deux précédents articles (disponibles ici et là), j'ai évoqué à plusieurs reprises la notion de NUMA sans trop la détailler. NUMA (NonUniform Memory Access) est devenue l'une des architectures matérielles la plus utilisée dans la conception des serveurs. Je profite donc de cet article pour revenir sur son intégration dans Solaris (notamment les versions 10 et 11).

En théorie, une machine NUMA est composée d'une ou plusieurs nodes disposant chacune d'un certain nombre de CPU(s) et d'une certaine quantité de mémoire. Toutes les nodes sont interconnectées entre elles et partagent l'intégralité mémoire de la machine. Les temps d'accès mémoire contenue dans une node sont inférieurs aux temps d'accès mémoire contenue dans une node distante (modèle de latence).

Un modèle de latence consiste le plus souvent à un ou plusieurs locality groups (lgrps). Chaque lgrp est constitué :

d'une ou plusieurs CPU(s)
d'une ou plusieurs pages de mémoire physiques

lgroup

A noter qu'il existe plusieurs modèles de latence plus ou moins complexes (différents niveaux de latence).

Solaris est "aware" de l'architecture matérielle NUMA : les différentes nodes sont des éléments connus du système Solaris. L'association mémoire / CPUs est connue de Solaris sous la forme de groupe de localité (locality group).

Le framework MPO (Memory Placement Optimization) est un composant essentiel à l'architecture NUMA. Pour une application en cours de fonctionnement, le système Solaris tente de l'exécuter sur une CPU la plus proche de la mémoire pour minimiser le plus possible les temps d'accès à celle-ci.

Quelques notions importantes à connaître :

Pour chaque nouveau thread un locality group est sélectionné (home lgrp)
L'algorithme d'ordonnancement tentera d'exécuter un thread sur une des CPUs de son home lgrp
La classe d'ordonnancement RT n'est pas prise en compte dans cet algorithme

Un thread peut changer de home lgrp uniquement si :

Le locality group est détruit
Le thread est binder sur une autre CPU d'un autre locality group

Plusieurs paramètres sont disponibles pour modifier le comportement des lgrps. Voir la section suivante : Locality Group Parameters dans Oracle Solaris Tunable Parameters Reference Manuel.

Maintenant, passons un peu à la pratique... Pour connaître le nombre de lgrps disponible sur un système, il existe deux méthodes : en utilisant la commande kstat ou en passant par mdb :

# kstat -m lgrp
module: lgrp             instance: 1
name:   lgrp1            class:    misc
    alloc fail           294068397
    cpus                 8
    crtime               343.726918435
    default policy       0
    load average         11296
    lwp migrations       1309
    next-seg policy      0
[...]

# mdb -k

Loading modules: [...]

> ::walk cpu |::print cpu_t cpu_lpl |::print lgrp_t lgrp_id !sort -u
lgrp_id = 0x6bdd
lgrp_id = 0x8356
lgrp_id = 0x840b
lgrp_id = 0xa232

La macro lgrp disponible dans mdb permet d'obtenir bien plus d'informations sur les lgrps dont notamment le nombre de CPUs et leurs répartitions. Attention cette macro n'est pas disponible dans toutes les updates de Solaris 10 :

# mdb -k
Loading modules: [...]
> ::lgrp
LGRPID             ADDR           PARENT    PLATHAND   #CPU    CPUS
      0 fffffffffbc20580                0     DEFAULT      0
      1 fffffffffbc0d440 fffffffffbc20580           0      8    0-7
      2 fffffffffbc0d4a8 fffffffffbc20580           1      8    8-15
      3 fffffffffbc0d510 fffffffffbc20580           2      8    16-23
      4 fffffffffbc0d578 fffffffffbc20580           3      8    24-31

Les statistiques des lgrps sont disponibles facilement via la commande kstat. Par exemple pour le lgrp 3, il suffit de saisir la commande suivante :

$ kstat -m lgrp -i 3
module: lgrp                       instance: 3
name:   lgrp3                      class:    misc
    alloc fail                     557701
    cpus                           8
    crtime                         345.278084135
    default policy                 0
    load average                   48125
    lwp migrations                 41345
    next-seg policy                0
    next-touch policy              9959223943
    pages avail                    33554432
    pages failed to mark           0
    pages failed to migrate from   0
    pages failed to migrate to     0
    pages free                     6976717
    pages installed                33554432
    pages marked for migration     0
    pages migrated from            0
    pages migrated to              0
    random policy                  5496062
    round robin policy             0
    snaptime                       8170819.92639302
    span process policy            0
    span psrset policy             0

Pour obtenir le home lgrp d'un thread en cours d'exécution, il suffit d'utiliser mdb (l'adresse du lgrp est stockée dans la structure kthread_t) :

# mdb -k

Loading modules: [...]

> 0t26116::pid2proc |::walk thread |::print kthread_t t_lpl |::print struct lgrp_ld lpl_lgrpid

lpl_lgrpid = 0x4

Lors de la création d'un thread, il suffit d'utiliser le one-liner Dtrace ci-dessous pour connaître rapidement son home lgrp :

# dtrace -qn 'thread_create:return { printf("Created thread (PID %d LWP %d) with home lgroup %d\n", pid, tid, curthread->t_lpl->lpl_lgrpid); }"
Created thread (PID 26539 LWP 1) with home lgroup 3
Created thread (PID 26743 LWP 1) with home lgroup 2
Created thread (PID 26745 LWP 1) with home lgroup 4
Created thread (PID 5913 LWP 1) with home lgroup 3
Created thread (PID 26745 LWP 1) with home lgroup 4
Created thread (PID 18609 LWP 26478) with home lgroup 3
Created thread (PID 18609 LWP 26478) with home lgroup 3
Created thread (PID 26757 LWP 1) with home lgroup 4
Created thread (PID 2473 LWP 7) with home lgroup 4
Created thread (PID 26754 LWP 1) with home lgroup 4
^C
Created thread (PID 26763 LWP 1) with home lgroup 1
Created thread (PID 26771 LWP 1) with home lgroup 2

En théorie, un thread sera le plus souvent exécuté sur les CPUs disponibles dans son home lgrp. Pour vérifier cela, j'utilise un petit script Dtrace (inspiré du script getlgrp.d disponible dans Solaris Internals - attention j'ai du modifié quelque peu le code pour qu'il fonctionne sur les dernières versions de Solaris 10) :

# mdb -k

Loading modules: [...]

> 0t11517::pid2proc |::walk thread |::print kthread_t t_lpl |::print struct lgrp_ld lpl_lgrpid
lpl_lgrpid = 0x4

# ./lgrp.d 11517
^C
Threads CPUs and lgrps for PID 11517

TID   LGRP     CPUID    COUNT
================================
1     2        8        2
1     1        2        4
1     1        7        5
1     1        3        6
1     1        5        6
1     1        6        6
1     2        9        6
1     2        10       6
1     2        13       6
1     1        0        7
1     2        11       7
1     1        4        8
1     2        12       8
1     2        15       8
1     1        1        9
1     3        16       9
1     3        20       9
1     3        22       9
1     2        14       10
1     3        21       10
1     3        17       11
1     3        23       11
1     3        19       12
1     3        18       13
1     4        26       216
1     4        31       226
1     4        28       246
1     4        24       247
1     4        29       298
1     4        25       308
1     4        27       342
1     4        30       370

Dans cet exemple, le processus 11517 contient un seul lwp. On constate que celui-ci est exécuté majoritairement sur les différentes CPUs du lgrp 4. L'algorithme du MPO effectue correctement son travail pour favoriser l'exécution du processus sur son home lgrp.

Lors de la création d'un fils (processus ou thread), le système Solaris tente de sélectionner une CPU dans le home lgrp du père. Cependant si les ressources souhaitées (notamment mémoire) ne sont pas disponibles, le système choisit alors un nouveau home lgrp pour ce fils.

Pour observer ces évènements, j'utilise la fonction lgrp_move_thread() :

# ./lgrpmove.d

Thread 1 (pid 13222) from Home lgrp 4 rehomed to New lgrp 3
Thread 1 (pid 18776) from Home lgrp 1 rehomed to New lgrp 2
Thread 1 (pid 18774) from Home lgrp 1 rehomed to New lgrp 4
Thread 864 (pid 18800) from Home lgrp 4 rehomed to New lgrp 2
Thread 1 (pid 18816) from Home lgrp 3 rehomed to New lgrp 1
Thread 1 (pid 18822) from Home lgrp 2 rehomed to New lgrp 1
Thread 1 (pid 15869) from Home lgrp 4 rehomed to New lgrp 3
Thread 1 (pid 15944) from Home lgrp 2 rehomed to New lgrp 1
Thread 1 (pid 18843) from Home lgrp 2 rehomed to New lgrp 3
Thread 1 (pid 15869) from Home lgrp 4 rehomed to New lgrp 3
Thread 1 (pid 15869) from Home lgrp 4 rehomed to New lgrp 3
Thread 1 (pid 18864) from Home lgrp 4 rehomed to New lgrp 1
Thread 1 (pid 15944) from Home lgrp 2 rehomed to New lgrp 1
Thread 1 (pid 18855) from Home lgrp 3 rehomed to New lgrp 2
Thread 1 (pid 18880) from Home lgrp 2 rehomed to New lgrp 3

^C

Thread 1 (pid 18863) from Home lgrp 1 rehomed to New lgrp 3
Thread 1 (pid 18857) from Home lgrp 4 rehomed to New lgrp 3

Dans Solaris 11, nous disposons deux nouvelles commandes lgrpinfo et plgrp pour consulter et changer le home lgrp d'un thread (Je vous encourage à consulter avec attention les pages de manuels de ces deux nouvelles commandes).

La commande lgrpinfo affiche toutes les informations sur les lgrps :

# lgrpinfo
lgroup 0 (root):
        Children: 1 2
        CPUs: 0-11
        Memory: installed 48G, allocated 2.8G, free 45G
        Lgroup resources: 1 2 (CPU); 1 2 (memory)
        Latency: 70197
lgroup 1 (leaf):
        Children: none, Parent: 0
        CPUs: 0 2 4 6 8 10
        Memory: installed 24G, allocated 915M, free 23G
        Lgroup resources: 1 (CPU); 1 (memory)
        Load: 0.168
        Latency: 48058
lgroup 2 (leaf):
        Children: none, Parent: 0
        CPUs: 1 3 5 7 9 11
        Memory: installed 24G, allocated 1.9G, free 22G
        Lgroup resources: 2 (CPU); 2 (memory)
        Load: 0.0259
        Latency: 48058

Pour obtenir le home lgrp d'un thread, il suffit simplement simplement de saisir la commande plgrp :

# plgrp $$
PID/LWPID HOME
2947/1 2

L'exécution d'une application bénéficiant du meilleur placement est un axe d'optimisation de plus en plus important. Plusieurs recherches vont dans ce sens : après MPO dans Solaris 9 et 10, Solaris 11 utilise aussi des algorithmes de placements pour les I/O (NUMA I/O). Affaire à suivre...

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

Chapitre 16 "Support for NUMA and CMT Hardware" dans Solaris internals
Chapitre 3 "Scheduling Classes and the Dispatcher" dans Solaris internals
OpenSolaris NUMA Project
Querying locality groups (Darryl Gove's blog)

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

12 février 2012 7 12 /02 /février /2012 15:20

Intimate Shared Memory (ISM) et Solaris x86 (workarounds)

Après avoir rencontré quelques anomalies dans la gestion de ISM sous Solaris x86 (voir l'analyse du bug), nous allons étudier la manière de le contourner. Pour rappel le bug est le suivant : non partage de la table de pages en ISM. Les workarounds mis en oeuvre ici concernent uniquement les bases de données Oracle. Cependant certains d'entre eux peuvent vous aider à adresser ce type de problème dans contextes différents. Je remercie Alain et Thierry (consultants Oracle) pour l'aide apportée sur la mise en place de ces workarounds (notamment sur la partie Oracle base de données).

Ce bug a toujours existé dans Solaris 10x86, et pourtant personne ne l'a remarqué. Et pourquoi donc !? Il faut deux éléments pour qu'il devienne visisble sur le système :

Une taille de ISM importante (supérieur à 80 Go environ)
Une multitude d'attachements / détachements à cette ISM

Sans ces deux conditions, le dysfonctionnement n'est pas impactant pour le système (la consommation du serveur n'est pas affectée par des Spin locks provenant du bug). Il y a deux manières de controurner ce problème :

La taille de l'ISM
Diminuer le nombre d'attachements / détachements

Diminuer la taille de l'ISM va un peu à l'encontre de l'histoire !! Possédant des serveurs de plus en plus capacitifs (512 Go de RAM voir plus maintenant), et ne pas en profiter pleinement, c'est un peu ridicule. Une approche plus constructive serait de découper le segment ISM par plusieurs segments de plus petites tailles. Solaris a bien des qualités mais ne posséde malheuresement pas celle de découper un segment ISM (à l'inverse de Linux : voir shmmax et shmall).

Reste que le monde informatique est bien fait !! L'architecture des serveurs x86 (je parle des serveurs produits actuellement) fonctionne en utilisant le schéma mémoire NUMA. Pour simplifier, le temps d'accès à la mémoire dépend de sa localisation par rapport aux processeurs. Solaris utilise pleinement ces fonctionnalités à travers les locality groups (lgrp). La mémoire est implicitement découpée par le système Solaris. La base de données Oracle est capable de découper son segment de mémoire partagée sur les différents locality groups disponibles sur le serveurs. Quand je vous disais que le monde informatique était bien fait !! Il s'agit d'activer une option lors du démarrage de la base de données.

L'autre approche est de limiter le nombre d'attachements / détachements. Même si diminuer le nombre d'utilisateurs reste une solution, je ne vous la conseille pas !! Par contre utiliser les fonctionnalités d'Oracle base de données nous permet de répondre à ce besoin. Il s'agit d'utiliser soit la fonctionnalité de Shared Server soit la fonctionnalité de Database Resident Connection Pooling. La dernière fonctionnalité étant disponible en version 11g.

Le protocol de tests est assez simple : lancement de 50 connexions simultanées (via sqlplus). Chaque sqlplus provoque une connexion / déconnexion à la base toutes les 2 secondes. L'activité du système est surveillée par la commande vmstat, les locks (et leurs temps) sont tracés avec un petit script Dtrace. Tous les tests ont été réalisés avec une SGA de 200 Go et 25 Go de shared pool.

Résultats obtenus :

Cas 1 : Reproduction du problème

Paramétrage	Aucun
Durée des 50 connexions	2m16s
Charge CPU	Saturé en mode Système
Nombre de locks Spin et Block	Des milliers de Spin et Block
Temps des locks Spin	Spin de quelques ms à 700ms
Temps des locks Block	Block de quelques ms à plusieurs milliers de ms

Cas 2 : Utilisation de NUMA

Paramétrage	Activation de NUMA
Durée des 50 connexions	32s
Charge CPU	60% en mode système - 5% en mode user
Nombre des locks Spin et Block	Des milliers de Spin et Block
Temps des locks Spin	Spin inférieur à 1ms
Temps des locks Block	Block compris entre 10ms et 100ms

Remarques :

4 lgrps disponibles sur le serveur
3 segments ISM de 50 Go + 1 segment ISM de 75 Go (50 Go de SGA et 25 Go PGA)
1 segment ISM de quelques Mo pour la gestion des 4 autres segments

Cas 3 : Utilisation de Data Resident Connection Pooling dans Oracle

Paramétrage	Activation du Data Resident Connection Pooling
Durée des 50 connexions	26s
Charge CPU	Inférieur à 5% en mode système et user
Nombre des locks Spin et Block	Quelques appels lors de la création des processus de pool
Temps des locks Spin	Quelques nanosecondes
Temps des locks Block	Aucun

Remarques :

Lors du test, un hang non expliqué est apparu
Les limitations fonctionnelles de connexions au même schéma sont à valider par l'applicatif

Cas 4 : Utilisation de Shared Server

Paramétrage	Activation des Shared Server
Durée des 50 connexions	24s
Charge CPU	Inférieur à 5% en mode système et user
Nombre des locks Spin et Block	Quelques appels lors de la création des processus de pool
Temps des locks Spin	Quelques nanosecondes
Temps des locks Block	Aucun

Remarques :

Quelques ajustements à faire : nombre de serveurs, large pool, taille de la UGA
Fonctionnalités présentes depuis plusieurs versions d'Oracle base de données

Les 3 workarounds présentés ici permettent d'augementer la taille de la SGA de votre base Oracle sur Solaris x86 sans saturer votre système. Les fonctionnalités présentes dans Oracle (Data Resident Connection Pooling et Shared Servers) permettent même de masquer complétement le bug ISM : les attachements / détachements sont supprimés. Cependant leur mise en oeuvre nécessite un paramétrage à faire valider par les utilisateurs. L'option NUMA est plus simple à mettre en oeuvre mais dépend surtout de votre architecture matérielle : nombre de lgrps disponibles sur votre système (j'écris en ce moment un petit artcile à ce sujet).

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

Chapitre 16 "Support for NUMA and CMT Hardware" dans Solaris internals
Application and Networking Architecture in Oracle DB
Configuring Oracle Database for Shared Server
Tuning Shared Server
About Databe Resident Connection Pooling
Configuring Database Resident Connection Pooling

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

31 janvier 2012 2 31 /01 /janvier /2012 23:03

Intimate Shared Memory (ISM) et Solaris x86 (2eme partie)

Continuons un peu cette formidable aventure dans la gestion de l'ISM sous Solaris x86. Dans l'article précédent, j'évoque un problème d'initialisation de l'ISM provenant des tailles de pages. Dans cet article, j'ai découvert un bug dans la gestion de l'ISM toujours sous Solaris x86.

Suite à une migration d'une base de données Oracle d'une architecture Solaris Sparc à une architecture Solaris x86, l'équipe DBA a décidé d'utiliser pleinement la mémoire disponible sur cette nouvelle infrastructure. Disposant d'un serveur avec 512 Go de mémoire, la SGA de la base Oracle a été positionnée à 290 Go (afin de diminuer les lectures physiques et d'éviter les locks R/W). L'augmentation de cette SGA a eu un bénéfice important sur les opérations de lectures (plus d'activité sur les disques SAN concernant les lectures) par contre le système Solaris saturait...

# vmstat 3
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr s0 s1 s6 s7 in sy cs us sy id
11 2 0 274157192 335523004 1348 8439 1506 2 2 0 1 5 -1 158 105 15844 31218 10183 5 7 88
2 12 0 86340852 144652404 1996 43583 0 25 24 0 0 0 0 0 0 64086 182685 44871 13 34 53
2 0 0 86352032 144645428 4773 45640 0 17 17 0 0 0 0 0 0 179020 200275 59466 16 31 53
0 1 0 86327500 144637200 1680 42171 0 35 33 0 0 0 0 0 0 69311 178558 44632 14 40 46
2 0 0 86357008 144655832 2035 35481 0 13 13 0 0 0 0 0 0 62857 162021 45164 13 25 63
2 0 0 86334148 144631452 1940 44848 0 11 11 0 0 0 0 0 0 64294 188696 43993 13 38 49
1 1 0 86171376 144496048 3014 52949 0 5 5 0 0 0 0 0 0 64821 192942 46708 17 30 52
52 1 0 86025360 144381188 1779 38176 0 16 16 0 0 0 0 0 0 47234 129932 29021 13 64 24
2 0 0 85953152 144301940 1766 50384 0 21 20 0 0 5 0 0 0 68138 181369 40882 18 46 37
0 2 0 86124088 144497016 2889 38238 0 11 11 0 0 0 0 0 0 53142 151981 36137 11 46 43
50 0 0 86065384 144470520 1806 46570 0 27 24 0 0 0 0 0 0 41055 147273 26207 9 71 20
2 0 0 86020672 144434312 1818 30717 8 3 1 0 0 0 0 0 0 59711 155183 37919 11 55 33
20 1 0 86000472 144415592 2892 46429 0 24 23 0 0 0 0 0 0 48937 161600 32703 12 66 23

^C

Le système saturait complètement lors de l'utilisation massive de la base de données. Avec un load de plus 200 sur 5 minutes, un pourcentage de 80 pour le SYS et 20 pour le USER, quelques choses ne fonctionnait pas correctement.

Passons à l'analyse de ce problème. D'abord, qui utilise le temps système ?

# dtrace -n 'profile-1001hz /arg0/ { @[execname] = count(); }'
dtrace: description 'profile-1001hz ' matched 1 probe
^C
[…]
mpathadm 1102
fsflush 2160
tnslsnr 4541
sched 37200
oracle 496331

Le temps système provient des process Oracle DB. Une bonne chose mais cela reste étrange. Que fait Oracle pour consommer autant de temps système ?

# dtrace -n 'profile-1001hz /arg0 && execname == "oracle" / { @[stack()] = count(); } tick-60s { trunc(@,5); exit(0);}'
dtrace: description 'profile-1001hz ' matched 2 probes
CPU ID FUNCTION:NAME
19 73222 :tick-60s

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_get+0x62
shmsys`shmget+0x4a
shmsys`shmsys+0x7e
unix`sys_syscall+0x17b
83649

unix`mutex_delay_default+0xa
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lock+0x11
shmsys`shm_detach+0x5c
shmsys`shmdt+0x90
shmsys`shmsys+0x6d
unix`sys_syscall+0x17b
94488

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lock+0x11
shmsys`shm_detach+0x5c
shmsys`shmdt+0x90
shmsys`shmsys+0x6d
unix`sys_syscall+0x17b
108405

unix`mutex_delay_default+0xa
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lookup+0x29
shmsys`shmat+0x70
shmsys`shmsys+0x59
unix`sys_syscall+0x17b
129651

unix`mutex_delay_default+0x7
unix`mutex_vector_enter+0x99
ipc`ipc_lock_internal+0x4b
ipc`ipc_lookup+0x29
shmsys`shmat+0x70
shmsys`shmsys+0x59
unix`sys_syscall+0x17b
147262

Fort intéressant !? Lors des appels systèmes shmat() et shmdt(), le système consomme son temps dans des mutex. Regardons cela de plus près. S'aggissant de locks type adaptive mutex, deux choses sont à vérifier :

le temps d'acquisition de la ressource (cpu off donc mutex adaptive block)
le temps écoulé pendant l'obtention de la ressource (cpu on donc mutex spin)

J'ai écrit rapidement un petit script Dtrace me permettant de quantifier rapidement ces deux temps (j'utilise notamment la probe lockstat). Ci-joint le résultat

# ./ipc_lock.d

558462664068813 cpu 4 exec oracle pid 23796: adaptive-block(0) took 1015 ms
558461944173547 cpu 28 exe oracle pid 23864: adaptive-block(0) took 1185 ms
558462329451173 cpu 30 exe oracle pid 23886: adaptive-spin(0) took 2570 ms
558462329430767 cpu 31 exe oracle pid 23724: adaptive-spin(0) took 1930 ms
558463436775114 cpu 0 exec oracle pid 23906: adaptive-spin(0) took 1963 ms
558463900687630 cpu 0 exec oracle pid 22498: adaptive-spin(0) took 1598 ms
558463900815833 cpu 0 exec oracle pid 23165: adaptive-block(0) took 1088 ms
558463119973512 cpu 1 exec oracle pid 23840: adaptive-spin(0) took 2979 ms
558463900250335 cpu 2 exec oracle pid 23868: adaptive-spin(0) took 3515 ms
558463436925731 cpu 5 exec oracle pid 23786: adaptive-block(0) took 1397 ms
558463900448070 cpu 6 exec oracle pid 23808: adaptive-block(0) took 1199 ms
558463900426025 cpu 10 exec oracle pid 22343: adaptive-spin(0) took 1766 ms
558463436944972 cpu 14 exec oracle pid 23881: adaptive-block(0) took 1203 ms
558463775141403 cpu 15 exec oracle pid 23903: adaptive-spin(0) took 3979 ms
558463646477100 cpu 16 exec oracle pid 23858: adaptive-spin(0) took 3374 ms
558463545080417 cpu 17 exec oracle pid 23842: adaptive-block(0) took 1299 ms
558463775195434 cpu 20 exec oracle pid 23838: adaptive-block(0) took 1164 ms
558463775112272 cpu 21 exec oracle pid 23900: adaptive-spin(0) took 1893 ms
558464220990762 cpu 8 exec oracle pid 23471: adaptive-spin(0) took 1754 ms
558464221051681 cpu 15 exec oracle pid 23136: adaptive-spin(0) took 1967 ms
558466485966584 cpu 9 exec oracle pid 23903: adaptive-spin(0) took 1040 ms
558466153296593 cpu 16 exec oracle pid 23918: adaptive-spin(0) took 1597 ms
558467238545528 cpu 1 exec oracle pid 23855: adaptive-spin(0) took 1206 ms
558467660401004 cpu 8 exec oracle pid 23888: adaptive-spin(0) took 1917 ms
558466980614425 cpu 9 exec oracle pid 23938: adaptive-block(0) took 1141 ms
558466980595351 cpu 11 exec oracle pid 23930: adaptive-block(0) took 1354 ms
558467779687829 cpu 14 exec oracle pid 23955: adaptive-spin(0) took 2318 ms
558467976549814 cpu 4 exec oracle pid 23908: adaptive-spin(0) took 1210 ms
558467976490096 cpu 5 exec oracle pid 23641: adaptive-spin(0) took 1278 ms
558469750980230 cpu 3 exec oracle pid 23936: adaptive-spin(0) took 3297 ms
558469308862236 cpu 5 exec oracle pid 23911: adaptive-spin(0) took 1332 ms
558469308776939 cpu 7 exec oracle pid 23920: adaptive-spin(0) took 3390 ms
558469308793235 cpu 8 exec oracle pid 23890: adaptive-spin(0) took 3219 ms
558469308812116 cpu 10 exec oracle pid 23955: adaptive-spin(0) took 1413 ms
ˆC
558469750890183 cpu 11 exec oracle pid 23991: adaptive-spin(0) took 1774 ms

Ca se passe de commentaire non !? Plus de 3 secondes en moyenne pour les adaptive spin !!! Mais que se passe t'il exactement ? Lors de chaque attachement ou détachement à la SGA, le système lock la ressource IPC. En moyenne, il y a environ 20 attachements / détachements seconde sur cette base de données avec plus de 1000 connexions actives en simultanées (voir la colonne NATTCH).

# ipcs -mopi -z zonexxxx
IPC status from <running system> as of Tue Oct 23 10:14:51 CET 2011
T ID KEY MODE OWNER GROUP NATTCH CPID LPID ISMATTCH
Shared Memory:
m 520093698 0x77adb4f8 --rw-rw---- oracle dba 1338 29340 18826 1338

Voyons un peu plus dans le détail les différentes stack() kernel obtenus lors des locks adaptive spin et block.

# ./ipc_stack.d

unix`htable_release+0x93
unix`hati_load_common+0x12d
unix`hat_share+0x281
genunix`segspt_shmattach+0xd2
genunix`as_map_locked+0x102
genunix`as_map+0x4a
shmsys`shmat+0x500
shmsys`shmsys+0x59
genunix`dtrace_systrace_syscall+0xc7
unix`sys_syscall+0x17b
225

unix`htable_lookup+0x8c
unix`hati_load_common+0x5b
unix`hat_share+0x281
genunix`segspt_shmattach+0xd2
genunix`as_map_locked+0x102
genunix`as_map+0x4a
shmsys`shmat+0x500
shmsys`shmsys+0x59
genunix`dtrace_systrace_syscall+0xc7
unix`sys_syscall+0x17b
606

unix`htable_lookup+0x8c
unix`hat_unshare+0x7e
genunix`segspt_shmunmap+0x81
genunix`as_unmap+0x137
shmsys`shm_detach+0x4b
shmsys`shmdt+0x90
shmsys`shmsys+0x6d
genunix`dtrace_systrace_syscall+0xc7
unix`sys_syscall+0x17b
897

La fonction hat_share() semble assez intéressante à étudier. En regardant d'un peu plus près le code source, on constate l'élément suivant : suite à différentes conditions, soit la table de pages est partagée soit elle ne l'est pas (goto share - goto unshare). Si vous avez lu l'article précédant, un des avantages d'utiliser un segment ISM est justement de pouvois partager sa table de pages entre les différents processus se connectant à ce segment.

La fonction hati_load_command() exécutée dans la fonction hat_share() se déclenche uniquement dans le goto unshare. Tient donc, on utilise ISM et on ne partage pas la table de pages entre les différents processus !? Une des conditions provoque ce dysfonctionnement mais laquelle ? La taille de la SGA influence t'elle quelques choses ? Y a t'il une limite à la SGA ?

J'ai décidé de reprendre cette analyse sur différentes bases Oracles ayant des tailles de SGA différentes. Le résultat est surprenant... Pour chaque attachement à la SGA, la stack est identique. Cela veut dire que la table de pages n'est jamais partagée sur un Solaris 10x86 quand l'ISM est activé !!! Oupppsss !!! Cependant les temps de locks sont nettement inférieurs à la seconde et augementent quand la taille de la SGA augmente.

Pour résumé, l'ISM activé sur Solaris 10x86 ne partage pas la table de pages entre les différents processus qui y accèdent. Plus il y a d'attachements simultanés plus le phénomène s'accentue. Plus la taille de l'ISM est important plus les temps de locks sont importants. Avec toute ces petites informations j'ai ouvert un call chez Oracle. Le diagnostique s'avère exact, un bug a été ouvert en interne avec la référence suivante Bug 7127336: page table not shared for ISM segment on x64.

La correction du Bug semble assez complexe à mettre en oeuvre. J'ai donc travaillé avec les ingénieurs Oracle afin de trouver une solution temporaire à ce problème... Il va falloir attendre un peu pour les solutions...

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

Chapitre 4, chapitre 12 et chapitre 17 dans Solaris internals
Shared memory uncovered par Jim Mauro

Partager cet article

Published by gloumps - dans kernel
commenter cet article …

9 janvier 2012 1 09 /01 /janvier /2012 18:13

Intimate Shared Memory (ISM) et Solaris x86 (1er partie)

Petit sujet qui m'a tenu en haleine. Pour faciliter sa compréhension je le découpe en deux parties : une première partie sur un problème d'initialisation d'un segment de type ISM et une seconde partie sur un dysfonctionnement de l'ISM. Les deux sous Solaris x86 uniquement.

Mais de quoi parlons nous ? Quelques explications sont nécessaires. Pour partager des données et synchroniser des évènements entre processus, le système Solaris utilise un framework nommé IPC (InterProcess Communication). Ce framework contient plusieurs objets IPC dont le standard POSIX IPC : POSIX semaphores, POSIX shared memory et POSIX message queues.

J'évoque ici l'objet IPC : POSIX shared memory. Cet objet est notamment utilisé dans les bases de données (en tout cas Oracle et Sybase). Pour les "spécialistes" de ces produits, il s'agit ni plus ni moins de la fameuse SGA. Pour nous, les "spécialistes" du système nous appelons cela un segment SHM (Segment sHared Memory). Lors du démarrage d'une instance Sybase ou Oracle, un segment SHM est initialisé avec une taille spécifique. Si cette taille n'est pas disponible, l'instance ne s'active pas.

Par défaut, la création d'un segment SHM :

n'est pas locké en mémoire (donc swappable).
utilise des tailles de pages par défaut (soit 4K sous Solaris x86 et 8K sous Solaris sparc).
n'utilise pas de table de translation d'addresse commune entre tous les processus utilisants ce segment.

Les ingénieurs Solaris ont donc optimisé la gestion de ce segment SHM : ISM (Intimate Shared Memory).

L'ISM corrige les problèmatique d'un segment SHM classique :

taille de pages optimisée.
création d'une table de partage d'adresse pour optimiser les translation.
segment automatiquement locké en mémoire.

L'utilisation de ce type de segment est devenu le standard pour les bases de données : la SGA fonctionne donc avec un segment ISM sous Solaris.

D'où mon problème : ma base de données Oracle 11g r2 sous Solaris 10x86 (update 9) n'utilise pas un segment ISM mais un simple segment SHM !!! Analysons un peu tout cela.

En espectant l'espace d'adresse du process Oracle (ici pmon), j'ai étais surpris de constater que la SGA utilisait un segment SHM classique :

# pmap -x 10735
10735: ora_pmon_XXXX22
         Address   Kbytes       RSS    Anon   Locked Mode   Mapped File
0000000000400000   222240     91144       -     - r-x--   oracle
000000000DD17000     1180       676     208       - rw---   oracle
000000000DE3E000      136        32      32       - rw---   oracle
000000000DE60000     1828      1644    1632       - rw---   [ heap ]
0000000060000000        4      4       -       - r--s-   [ shmid=0x4000003c ]
0000000060001000 2097156 2028692       -       - rwxs-   [ shmid=0x4000003c ]
FFFFFD7FFCAA0000       64         8       8       - rwx--   [ anon ]
FFFFFD7FFCABE000       72         8       8       - rw---   [ anon ]
FFFFFD7FFCAD0000       64        12      12       - rw---   [ anon ]
[...]

L'initialisation d'un segment type ISM provient du demandeur et non du système. J'ai donc décidé de vérifier les logs de démarrage de l'instance Oracle (fichier alert.log). Je suis tombé sur ce message fort intéressant :

Mon Nov 21 16:38:40 2011
Starting ORACLE instance (normal)
WARNING: Not enough physical memory for SHM_SHARE_MMU segment of size 0x0000000080002000 [flag=0x4000]

Lors de l'activation de l'instance, Oracle a tenté d'activer un segment type ISM sans y être parvenu. Le message indiquant l'erreur suivante : Not enough physical memory for SHM_SHARE_MMU segment. Tiens donc pas assez de mémoire ? Alors que la SGA demandée correspondait à seulement 2 Go ? La vérité était ailleurs...

Pour mieux reproduire le problème, j'ai décidé d'écrire un petit programme C me permettant de créer un segment type ISM. Contrairement à ce que je pensais, ce n'est pas lors de la création du segment que le type ISM est spécifié mais lors d'un attachement.

La création et l'attachement correspondent aux appels suivants :

shmget(2, size, 0660 | IPC_CREAT | IPC_EXCL)

shmat(shmid, (void *)0, SHM_SHARE_MMU)

Le flag SHM_SHARE_MMU de la fonction shmat permet l'utilisation de l'ISM. L'exécution de mon petit programme C m'a permis d'activer sans problème un segment ISM de 10 Go.

# ./ishm
shmid: 1526726689

# ipcs -m
IPC status from <running system> as of Tue Jan 10 11:26:10 CET 2012
T ID KEY MODE OWNER GROUP
Shared Memory:
m 1526726689 0x2 --rw-rw---- root root

[...]

# pmap -x 24680
24680: ./ishm
         Address   Kbytes       RSS Anon    Locked Mode   Mapped File
0000000000400000        4         4     -         - r-x-- ishm
0000000000410000        8         8     8         - rw--- ishm
FFFFFD7F80000000 1048576   1048576     -   1048576 rwxsR [ ism shmid=0x5b000021 ]
FFFFFD7FFF210000       64        64    64         - rwx-- [ anon ]
FFFFFD7FFF230000       24        12    12         - rwx-- [ anon ]
FFFFFD7FFF240000     1276       712     -         - r-x-- libc.so.1
FFFFFD7FFF380000        4         4     4         - rwx-- [ anon ]
FFFFFD7FFF38F000       36        36    36         - rw--- libc.so.1
FFFFFD7FFF398000       16         4     4         - rw--- libc.so.1
FFFFFD7FFF3AE000      244       244     -         - r-x-- ld.so.1
FFFFFD7FFF3F0000        4         4     4         - rwx-- [ anon ]
FFFFFD7FFF3FB000        8         8     8         - rwx-- ld.so.1
FFFFFD7FFF3FD000        8         8     8         - rwx-- ld.so.1
FFFFFD7FFFDFE000        8         8     8         - rw--- [ stack ]
---------------- -------- --------- ----- ---------
        total Kb 1050280   1049692   156   1048576

Mais où était mon problème ? Oracle doit en faire un peu plus ? J'ai donc tracé les appels systèmes lors du démarrage d'une instance.

[...]
6362:   shmget(672617948, 1073754112, 0660|IPC_CREAT|IPC_EXCL) = 83886086
6362:   shmget(672617949, 0, 0)                         Err#2 ENOENT
6362:   shmget(672617950, 0, 0)                         Err#2 ENOENT
6362:   shmget(672617951, 0, 0)                         Err#2 ENOENT
6362:   shmat(83886086, 0x60000000, 040000)             Err#22 EINVAL
6362:   shmat(83886086, 0x60000000, 0)                  = 0x60000000
[...]

Oracle s'attache en spécifiant une adresse mémoire 0x60000000. J'ai donc modifié mon petit programme C en spécifiant la même adresse d'attachement et j'ai obtenu à ma grande surprise l'erreur suivante :

# ./ishm
shmat: Invalid argument

J'ai obtenu la même erreur que le démarrage de la base Oracle. Bingo ! Lors de l'appel à la fonction shmat (si on spécifie l'adresse 0x60000000) l'attachement ne s'effectue pas. Mais pourquoi ? Dépassant un peu mes compétances j'ai ouvert un call au support Oracle.

Réponse du support Oracle : la valeur 0x60000000 n'est pas divisible (valeur entière) par l'ensemble des tailles de pages disponibles sur le système Solaris 10x86. Il faut donc désactiver la taille de pages posant problème (option désactivée dans le kernel patch suivant 144489-17). Le workaround n'est pas applicable en production (boot en mode kernel debugging + modification avant chargement du kernel de la valeur largepagesupport).

En vérifiant mes tailles de pages disponibles sur mon serveur DL380 G7, j'obtiens le résultat suivant :

# pagesize -a
4096
2097152
1073741824

Tiens donc, on peut utiliser des tailles de pages de 1Go !? Et bizarrement c'est avec cette taille de pages où la valeur 0x60000000 n'est pas divisible en une valeur entière. L'application du patch supprime la possibilité d'utiliser cette taille de pages.

Voilà donc la fin de la 1er partie sur ISM et Solaris 10x86. La 2ème partie fait référence à un bug dans la gestion de l'ISM uniquement pour Solaris 10x86 (et Solaris 11x86). Bug que j'ai eu le privilège de découvrir en exclusivité...

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