RE: Long spins or onstst -g spi. Need any information.

I dont think your systems has long spins... A long spin is by definition 10,000 spins while waiting on a latch for a resource My understanding of onstat -g spi is that it prints out all resources in the system which had to wait on a latch for a resource, not just long spins. Will >===== Original Message From Eugene Nechayev <4new@my-deja.com> ===== >Hi Informixers > >Can somebody provide me any information about "onstat -g spi" command. >I'm very interested in an information about "Name" column. What does >the different names really mean ? > >Okay my system has long spins > >onstat -g sch> >VP Scheduler Statistics: > vp pid class semops busy waits spins/wait > 1 1622 cpu 40 40 1001 > 2 1639 adm 0 0 0 > 3 1641 cpu 60 60 1001 > 4 1642 lio 4 0 0 > 5 1646 pio 4 0 0 > 6 1648 aio 764 0 0 > 7 1659 msc 34663 0 0 > 8 1667 aio 712 0 0 > 9 1671 soc 2 2 1000 > 10 1758 lio 1 0 0 > 11 1759 pio 2 0 0 > >However how can I recognize what's going on >from onstat -g spi output ? > >Spin locks with waits: > >Num Waits Num Loops Avg Loop/Wait Name >12203 14492 1.19 mtcb sleeping_lock >9 9 1.00 mtcb tcb_queue_lock >835 938 1.12 mtcb mutex_list_lock >254 263 1.04 mtcb cond_list_lock >31 926 29.87 mtcb notify_lock >11409 17405 1.53 vproc vp_lock, id = 1 >14466 21285 1.47 vproc vp_lock, id = 3 >13 1075 82.69 vproc vp_lock, id = 7 >118 538 4.56 mutex lock, name = rstcb >33 64 1.94 mutex lock, name = session >1 1 1.00 mutex lock, name = timestmp >24 44 1.83 mutex lock, name = deadlock >33 63 1.91 mutex lock, name = asf_global >19 26 1.37 mutex lock, name = guard >5 5 1.00 mutex lock, name = ddh chain >4 505 126.25 mutex lock, name = ddh chain >4 505 126.25 mutex lock, name = ddh chain >17 19 1.12 mutex lock, name = MGM mutex >1 1 1.00 mutex lock, name = vpc >1 3 3.00 mutex lock, name = vpc >140 233 1.66 mutex lock, name = sm_bflist >9 14 1.56 mutex lock, name = sm_close >100 149 1.49 mutex lock, name = sm_bcnt >157 246 1.57 mutex lock, name = sm_bflist >10 10 1.00 mutex lock, name = sm_close >102 157 1.54 mutex lock, name = sm_bcnt >1 3 3.00 mutex lock, name = log >1 1 1.00 mutex lock, name = pt_100002 >73 93 1.27 mutex lock, name = pt_200040 >1 3 3.00 mutex lock, name = pt_200046 >1 1 1.00 mutex lock, name = pt_20006a >24 29 1.21 mutex lock, name = pt_200077 >9 10 1.11 mutex lock, name = pt_200065 >14 2952 210.86 tcb lock, tid = 5 >3 1760 586.67 tcb lock, tid = 11 >2 1700 850.00 tcb lock, tid = 13 >1 81 81.00 tcb lock, tid = 15 >361 4013 11.12 shmcb sh_lock >46708 104866 2.25 pool po_lock, name = global >5695 11739 2.06 pool po_lock, name = mt >3 28 9.33 pool po_lock, name = aio >877 1934 2.21 pool po_lock, name = gls >78 87 1.12 fast mutex, lockhash[720] >8 8 1.00 fast mutex, lru-0 >2 2 1.00 fast mutex, lru-2 >12 15 1.25 fast mutex, lru-4 >15 46 3.07 fast mutex, lru-6 >10 136 13.60 fast mutex, lru-8 >2 2 1.00 fast mutex, lru-10 >4 4 1.00 fast mutex, lru-14 >15 16 1.07 fast mutex, lru-16 >8 11 1.38 fast mutex, lru-18 >2 4 2.00 fast mutex, lru-20 >11 1010 91.82 fast mutex, lru-22 >2 22 11.00 fast mutex, bf[7] >6 7 1.17 fast mutex, bf[313] >67 198 2.96 fast mutex, bf[325] >28 550 19.64 fast mutex, bf[327] >17 27 1.59 fast mutex, bf[329] >1 12 12.00 fast mutex, bf[331] >5 12 2.40 fast mutex, bf[335] >11 1010 91.82 fast mutex, lru-22 >2 22 11.00 fast mutex, bf[7] >6 7 1.17 fast mutex, bf[313] >67 198 2.96 fast mutex, bf[325] >28 550 19.64 fast mutex, bf[327] >17 27 1.59 fast mutex, bf[329] >1 12 12.00 fast mutex, bf[331] >5 12 2.40 fast mutex, bf[335] >1 1 1.00 fast mutex, bf[10718] >6 6 1.00 fast mutex, bf[10744] >54 83 1.54 fast mutex, SB bpool_lock > >Also onstat -g glo doesn't show that the system has long spins. > >MT global info: > >sessions threads vps lngspins > >9 44 11 0 > > sched calls thread switches yield 0 yield n yield >forever >total: 17393453 4499787 14116564 722346 180249 > >per sec: 829 173 723 5 5 > > > >Any help will be very appreciated. > >Regards, > >Eugene Nechayev > > >Sent via Deja.com http://www.deja.com/ >Before you buy. ------------------------------------------------------------ This e-mail has been sent to you courtesy of OperaMail, as a free service from Opera Software, makers of the award-winning Web Browser, Opera. Visit us at http://www.opera.com/ or our portal at: http://www.myopera.com/ Your free e-mail account is waiting at: http://www.operamail.com/ ------------------------------------------------------------

Hi William I thought so too, but my interpretation from documentation is that onstat -g sci shows long spins. Maybe it isn't correct However " - spi Prints spin locks that virtual processors have spun more than 10,000 times to acquire. These spin locks are called longspins. The total number of longspins is printed in the heading of the glo command. " p. 35-78 Administrator guide for IDS Version 7.3 February 1998. In this case if I have "Num Loops" = 14492 it means I have 14492 long spins and there isn't one process. Eugene Nechayev In article <807eha$6jb$1@news.xmission.com>, William Rice <ricew@operamail.com> wrote: > > I dont think your systems has long spins... > > A long spin is by definition 10,000 spins while waiting on a latch > for a resource > > My understanding of onstat -g spi is that it prints out all > resources in the system which had to wait on a latch > for a resource, not just long spins. > > Will > >===== Original Message From Eugene Nechayev <4new@my-deja.com> ===== > >Hi Informixers > > > >Can somebody provide me any information about "onstat -g spi" command. > >I'm very interested in an information about "Name" column. What does > >the different names really mean ? > > > >Okay my system has long spins > > > >onstat -g sch> > > >VP Scheduler Statistics: > > vp pid class semops busy waits spins/wait > > 1 1622 cpu 40 40 1001 > > 2 1639 adm 0 0 0 > > 3 1641 cpu 60 60 1001 > > 4 1642 lio 4 0 0 > > 5 1646 pio 4 0 0 > > 6 1648 aio 764 0 0 > > 7 1659 msc 34663 0 0 > > 8 1667 aio 712 0 0 > > 9 1671 soc 2 2 1000 > > 10 1758 lio 1 0 0 > > 11 1759 pio 2 0 0 > > > >However how can I recognize what's going on > >from onstat -g spi output ? > > > >Spin locks with waits: > > > >Num Waits Num Loops Avg Loop/Wait Name > >12203 14492 1.19 mtcb sleeping_lock > >9 9 1.00 mtcb tcb_queue_lock > >835 938 1.12 mtcb mutex_list_lock > >254 263 1.04 mtcb cond_list_lock > >31 926 29.87 mtcb notify_lock > >11409 17405 1.53 vproc vp_lock, id = 1 > >14466 21285 1.47 vproc vp_lock, id = 3 > >13 1075 82.69 vproc vp_lock, id = 7 > >118 538 4.56 mutex lock, name = rstcb > >33 64 1.94 mutex lock, name = session > >1 1 1.00 mutex lock, name = timestmp > >24 44 1.83 mutex lock, name = deadlock > >33 63 1.91 mutex lock, name = asf_global > >19 26 1.37 mutex lock, name = guard > >5 5 1.00 mutex lock, name = ddh chain > >4 505 126.25 mutex lock, name = ddh chain > >4 505 126.25 mutex lock, name = ddh chain > >17 19 1.12 mutex lock, name = MGM mutex > >1 1 1.00 mutex lock, name = vpc > >1 3 3.00 mutex lock, name = vpc > >140 233 1.66 mutex lock, name = sm_bflist > >9 14 1.56 mutex lock, name = sm_close > >100 149 1.49 mutex lock, name = sm_bcnt > >157 246 1.57 mutex lock, name = sm_bflist > >10 10 1.00 mutex lock, name = sm_close > >102 157 1.54 mutex lock, name = sm_bcnt > >1 3 3.00 mutex lock, name = log > >1 1 1.00 mutex lock, name = pt_100002 > >73 93 1.27 mutex lock, name = pt_200040 > >1 3 3.00 mutex lock, name = pt_200046 > >1 1 1.00 mutex lock, name = pt_20006a > >24 29 1.21 mutex lock, name = pt_200077 > >9 10 1.11 mutex lock, name = pt_200065 > >14 2952 210.86 tcb lock, tid = 5 > >3 1760 586.67 tcb lock, tid = 11 > >2 1700 850.00 tcb lock, tid = 13 > >1 81 81.00 tcb lock, tid = 15 > >361 4013 11.12 shmcb sh_lock > >46708 104866 2.25 pool po_lock, name = global > >5695 11739 2.06 pool po_lock, name = mt > >3 28 9.33 pool po_lock, name = aio > >877 1934 2.21 pool po_lock, name = gls > >78 87 1.12 fast mutex, lockhash[720] > >8 8 1.00 fast mutex, lru-0 > >2 2 1.00 fast mutex, lru-2 > >12 15 1.25 fast mutex, lru-4 > >15 46 3.07 fast mutex, lru-6 > >10 136 13.60 fast mutex, lru-8 > >2 2 1.00 fast mutex, lru-10 > >4 4 1.00 fast mutex, lru-14 > >15 16 1.07 fast mutex, lru-16 > >8 11 1.38 fast mutex, lru-18 > >2 4 2.00 fast mutex, lru-20 > >11 1010 91.82 fast mutex, lru-22 > >2 22 11.00 fast mutex, bf[7] > >6 7 1.17 fast mutex, bf[313] > >67 198 2.96 fast mutex, bf[325] > >28 550 19.64 fast mutex, bf[327] > >17 27 1.59 fast mutex, bf[329] > >1 12 12.00 fast mutex, bf[331] > >5 12 2.40 fast mutex, bf[335] > >11 1010 91.82 fast mutex, lru-22 > >2 22 11.00 fast mutex, bf[7] > >6 7 1.17 fast mutex, bf[313] > >67 198 2.96 fast mutex, bf[325] > >28 550 19.64 fast mutex, bf[327] > >17 27 1.59 fast mutex, bf[329] > >1 12 12.00 fast mutex, bf[331] > >5 12 2.40 fast mutex, bf[335] > >1 1 1.00 fast mutex, bf[10718] > >6 6 1.00 fast mutex, bf[10744] > >54 83 1.54 fast mutex, SB bpool_lock > > > >Also onstat -g glo doesn't show that the system has long spins. > > > >MT global info: > > > >sessions threads

Eugene Nechayev wrote: > > Hi William > > I thought so too, but my interpretation from documentation is > that onstat -g sci shows long spins. Maybe it isn't correct > > However > > " > - spi Prints spin locks that virtual processors have spun more > than 10,000 times to acquire. These spin locks are called > longspins. The total number of longspins is printed in the > heading of the glo command. > " > p. 35-78 > Administrator guide for IDS Version 7.3 February 1998. > > In this case if I have "Num Loops" = 14492 it means I have > 14492 long spins and there isn't one process. Ahh but those 14,492 loops are spread over 12,203 waits for an average spins per wait of 1.19 and since -spi shows no longspins (a single spin that needed more than 10,000 loops) then you can safely assume that almost all spins were <3 loops which is great. Besides you are pointing to the sleeping_lock which is used to do a short wait when there seems to be no work to do before the VP relinquishes the CPU. If your system is busy then this resource is always available and the spins/wait are few. If the system is quiet then all VPs are waiting on that lock at some point so the spins per wait for it will go up which is fine. This is used to avoid the VPs going to sleep just as work arrives and having to context switch again. The sleeping_lock is not one you need to watch. [SNIP] > > >from onstat -g spi output ? > > > > > >Spin locks with waits: > > > > > >Num Waits Num Loops Avg Loop/Wait Name > > >12203 14492 1.19 mtcb sleeping_lock [SNIP] Art S. Kagel

Art and William thanks for your responses Now it's more clear, and after Art's explaining line by line my onstat -g spi output it's more understandable and useful for me than after reading documentation sometimes ;-) Anyway I have a little bit strange situation that push me to investigation with spins/long spins from my point of view. I have two production systems both of them are working on HP 10.20 (K class ) + KAIO. The first is IDS 7.30 UC8 , box has 2CPU and I use Informix mirroring for all chunks. Informix Dynamic Server Version 7.30.UC8 -- On-Line -- Up 4 days 13:55:38 -- 214984 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 436366 1200189 134199264 99.67 582821 957649 22550995 97.42 isamtot open start read write rewrite delete commit rollbk 75947925 7828794 13045727 16731260 1312314 807349 177047 2424251 0 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 0 15629.49 833.67 320 2620 bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 77239 0 100570051 0 0 65 1012663 88447 ixda-RA idx-RA da-RA RA-pgsused lchwaits 99256 2173 105379 206354 6212 The second is IDS 7.30UC6 , single CPU box and doesn't use mirroring. ---------- Informix Dynamic Server Version 7.30.UC6 -- On-Line -- Up 3 days 18:10:50 -- 1 23152 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 8090294 8794030 87261031 90.73 1405503 3167509 8775788 83.98 isamtot open start read write rewrite delete commit rollbk 65979099 3436201 3992392 30468477 2545858 64792 394036 365717 2 gp_read gp_write gp_rewrt gp_del gp_alloc gp_free gp_curs 0 0 0 0 0 0 0 ovlock ovuserthread ovbuff usercpu syscpu numckpts flushes 0 0 1 21490.26 1046.83 530 1060 bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 630760 0 127029178 0 0 258 95131 68310 ixda-RA idx-RA da-RA RA-pgsused lchwaits 636140 1643 5546799 6176205 20 In general average load both instance is similar, but the first instance has a big spins (not long ;) ) list that I see every time when I run onstat -g spi , the second instance has only few lines for the same statistics. There are differences in onconfigs ---------- First Second MIRROR 1 MIRROR 0 RESIDENT 1 RESIDENT 0 MULTIPROCESSOR 1 MULTIPROCESSOR 0 NUMCPUVPS 2 NUMCPUVPS 1 SINGLE_CPU_VP 0 SINGLE_CPU_VP 1 AFF_SPROC 0 AFF_SPROC 0 AFF_NPROCS 2 AFF_NPROCS 0 LOCKS 130000 LOCKS 120000 BUFFERS 80000 BUFFERS 32000 PHYSBUFF 128 PHYSBUFF 64 LOGBUFF 128 LOGBUFF 64 LOGSMAX 52 LOGSMAX 230 CLEANERS 12 CLEANERS 9 SHMVIRTSIZE 36000 SHMVIRTSIZE 48000 SHMADD 16000 SHMADD 2048 CKPTINTVL 300 CKPTINTVL 600 LRUS 12 LRUS 12 LRU_MAX_DIRTY 20 LRU_MAX_DIRTY 20 LRU_MIN_DIRTY 5 LRU_MIN_DIRTY 10 STACKSIZE 128 STACKSIZE 64 RA_PAGES 128 RA_PAGES 16 RA_THRESHOLD 120 RA_THRESHOLD 8 OPTCOMPIND 0 OPTCOMPIND 2 LBU_PRESERVE 0 LBU_PRESERVE 1 NETTYPE ipcshm,2,50,CPU NETTYPE ipcshm,,200,CPU NETTYPE soctcp,1,20,NET NETTYPE soctcp,,25,NET PC_POOLSIZE 100 --- PC_HASHSIZE 197 --- I have no idea why the second instance has the small number of spins or vice versa ? Eugene Nechayev Sent via Deja.com http://www.deja.com/ Before you buy.

Eugene Nechayev <4new@my-deja.com> wrote in message news:80bvko$so0$1@nnrp1.deja.com... > Art and William thanks for your responses > > Now it's more clear, and after Art's explaining line by line > my onstat -g spi output it's more understandable and useful for me > than after reading documentation sometimes ;-) > > Anyway I have a little bit strange situation that push me to > investigation with > spins/long spins from my point of view. > > I have two production systems both of them are working on HP 10.20 (K > class ) > + KAIO. [...] '' ''''''' '''' '''''''''', '' '''''' ' '' ''''''', ''''' '''''', ''' '' ''' ''''''''' :) > In general average load both instance is similar, but the first instance > has a big > spins (not long ;) ) list that I see every time when I run onstat -g > spi , the > second instance has only few lines for the same statistics. > > There are differences in onconfigs > > ---------- > First Second > MIRROR 1 MIRROR 0 > NUMCPUVPS 2 NUMCPUVPS 1 ''' '''''' '' ''''''', ''' '''''' ''''''''' ''''' CPU VP ' '''''''' ' ''''''''' ''''''. '''' '' (CPU VP) ''''' '''' ''' '' '''''''''''''''' '''' '''''' ' '' '''''' '''' ''''' ''' '''''' ' '''''' ' '''' '' ''''''''''' ' ''''''. '''''' '''''''''''''' '''''''''' ' ''''''''. > SINGLE_CPU_VP 0 SINGLE_CPU_VP 1 > > AFF_SPROC 0 AFF_SPROC 0 > AFF_NPROCS 2 AFF_NPROCS 0 > > LOCKS 130000 LOCKS 120000 > BUFFERS 80000 BUFFERS 32000 > PHYSBUFF 128 PHYSBUFF 64 > LOGBUFF 128 LOGBUFF 64 > LOGSMAX 52 LOGSMAX 230 > CLEANERS 12 CLEANERS 9 > > SHMVIRTSIZE 36000 SHMVIRTSIZE 48000 > SHMADD 16000 SHMADD 2048 > CKPTINTVL 300 CKPTINTVL 600 > LRUS 12 LRUS 12 ' '' ''''' '''''''' '' '' '''''''''''' LRUS ? > LRU_MAX_DIRTY 20 LRU_MAX_DIRTY 20 > LRU_MIN_DIRTY 5 LRU_MIN_DIRTY 10 > STACKSIZE 128 STACKSIZE 64 > > RA_PAGES 128 RA_PAGES 16 > RA_THRESHOLD 120 RA_THRESHOLD 8 > > OPTCOMPIND 0 OPTCOMPIND 2> > LBU_PRESERVE 0 LBU_PRESERVE 1 > > NETTYPE ipcshm,2,50,CPU NETTYPE ipcshm,,200,CPU > NETTYPE soctcp,1,20,NET NETTYPE soctcp,,25,NET > > PC_POOLSIZE 100 --- > PC_HASHSIZE 197 ---> > > I have no idea why the second instance has the small number of spins or > vice versa ? > > > Eugene Nechayev > > > > Sent via Deja.com http://www.deja.com/ > Before you buy. -- ' ''''''''', ''''''' '''''''''