Speed issues 9.4

I am not sure what has happened but over the last week we went from zero complaints about speed to a lot of complaints. No app changes. The DB Server is a Sun V490 with 24 FC 15k drives configured as Raid 10. Checkpoints are averaging 0 seconds. IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 days 03:42:4 8 -- 2612224 Kbytes Profile dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached 228057060 779495368 2164074103 89.61 12488020 47951408 124371428 91.10 isamtot open start read write rewrite delete commit rollbk 1074256246 94337976 369843143 3789933033 43977852 7225917 4844460 1843268 213 4 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 61744.94 22718.42 602 1488 bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress seqscans 23845959 2399 3763015321 0 0 386 1045516 4462000 ixda-RA idx-RA da-RA RA-pgsused lchwaits 21349917 2718532 80138637 103942631 694834 onstat -g iov IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 days 03:39:2 6 -- 2612224 Kbytes AIO I/O vps:class/vp s io/s totalops dskread dskwrite dskcopy wakeups io/wup errors kio 0 s 116.6 51897068 49539166 2357902 0 98048287 0.5 0 kio 1 i 111.2 49480269 46984299 2495970 0 93220077 0.5 0 kio 2 s 30.4 13534186 12093534 1440652 0 24848841 0.5 0 kio 3 s 63.5 28278503 26432019 1846484 0 52454339 0.5 0 kio 4 i 14.9 6640466 5595584 1044882 0 12376862 0.5 0 kio 5 i 20.4 9081038 7929376 1151662 0 16730461 0.5 0 kio 6 s 45.1 20064775 18232398 1832377 0 36375647 0.6 0 msc 0 i 0.9 396585 0 0 0 395863 1.0 0 aio 0 i 0.5 216593 64458 20553 0 216504 1.0 0 aio 1 i 0.0 127 30 2 0 194 0.7 0 aio 2 i 0.0 9 5 0 0 14 0.6 0 aio 3 i 0.0 10 4 0 0 6 1.7 0 aio 4 i 0.0 8 1 0 0 4 2.0 0 aio 5 i 0.0 7 1 0 0 4 1.8 0 aio 6 i 0.0 4 1 0 0 3 1.3 0 pio 0 i 0.0 0 0 0 0 1 0.0 0 lio 0 i 0.0 0 0 0 0 1 0.0 0 db1:/ # onstat -R IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 days 03:39:4 7 -- 2612224 Kbytes 128 buffer LRU queue sets priority levels # type set total % of length LOW HIGH 0 f 7031 99.8% 7020 6191 829 1 m 0.2% 11 2 9 2 f 7031 99.7% 7010 6200 810 3 m 0.3% 21 6 15 4 f 7031 99.7% 7012 6228 784 5 m 0.3% 19 4 15 6 f 7032 99.7% 7012 6174 838 7 m 0.3% 20 5 15 8 f 7031 99.7% 7013 6204 809 9 m 0.3% 18 3 15 10 f 7032 99.8% 7021 6193 828 11 m 0.2% 11 2 9 12 f 7031 99.7% 7008 6171 837 13 m 0.3% 23 4 19 14 f 7032 99.6% 7005 6146 859 15 m 0.4% 27 5 22 16 f 7031 99.6% 7003 6212 791 17 m 0.4% 28 5 23 18 f 7031 99.6% 7003 6171 832 19 m 0.4% 28 8 20 20 f 7031 99.6% 7003 6183 820 21 m 0.4% 28 5 23 22 f 7031 99.5% 6999 6181 818 23 m 0.5% 32 7 25 24 f 7031 99.7% 7013 6213 800 25 m 0.3% 18 6 12 26 f 7031 99.6% 7006 6211 795 27 m 0.4% 25 4 21 28 f 7031 99.8% 7015 6202 813 29 m 0.2% 16 8 8 30 f 7031 99.6% 7001 6156 845 31 m 0.4% 30 4 26 32 f 7031 99.5% 6999 6183 816 33 m 0.5% 32 7 25 34 f 7032 99.7% 7008 6225 783 35 m 0.3% 24 5 19 36 f 7032 99.7% 7011 6187 824 37 m 0.3% 21 4 17 38 f 7031 99.6% 7001 6157 844 39 m 0.4% 30 4 26 40 f 7032 99.5% 6995 6192 803 41 m 0.5% 37 11 26 42 f 7033 99.6% 7002 6145 857 43 m 0.4% 31 5 26 44 F 7030 99.7% 7010 6183 827 45 m 0.3% 20 5 15 46 f 7031 99.7% 7011 6214 797 47 m 0.3% 20 6 14 48 f 7031 99.7% 7013 6214 799 49 m 0.3% 18 3 15 50 f 7031 99.6% 7003 6216 787 51 m 0.4% 28 6 22 52 f 7032 99.7% 7014 6161 853 53 m 0.3% 18 3 15 54 f 7031 99.6% 7002 6206 796 55 m 0.4% 29 5 24 56 f 7031 99.5% 6996 6195 801 57 m 0.5% 35 9 26 58 f 7032 99.8% 7018 6215 803 59 m 0.2% 14 3 11 60 f 7031 99.7% 7012 6179 833 61 m 0.3% 19 3 16 62 f 7031 99.7% 7012 6217 795 63 m 0.3% 19 1 18 64 f 7032 99.6% 7003 6202 801 65 m 0.4% 29 6 23 66 f 7032 99.6% 7002 6175 827 67 m 0.4% 30 4 26 68 f 7031 99.6% 7006 6229 777 69 m 0.4% 25 2 23 70 f 7032 99.8% 7020 6217 803 71 m 0.2% 12 1 11 72 f 7031 99.7% 7013 6196 817 73 m

> seqscans ==> 4462000 i would go after that; its a pitty that you do no thave a 'good' onstat -p i would set TABLESPACESTATS = 1 in onconfig bounce and look at sysmaster:sysptprof Superboer Gary Quiring schreef: > I am not sure what has happened but over the last week we went from > zero complaints about speed to a lot of complaints. No app changes. > The DB Server is a Sun V490 with 24 FC 15k drives configured as Raid > 10. > > Checkpoints are averaging 0 seconds. > > IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 > days 03:42:4 > 8 -- 2612224 Kbytes> > Profile > dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits %cached > 228057060 779495368 2164074103 89.61 12488020 47951408 124371428 > 91.10 > > isamtot open start read write rewrite delete > commit rollbk > 1074256246 94337976 369843143 3789933033 43977852 7225917 4844460 > 1843268 213 > 4 > > 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 61744.94 22718.42 602 1488 > > bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress > seqscans > 23845959 2399 3763015321 0 0 386 1045516 > 4462000 > > ixda-RA idx-RA da-RA RA-pgsused lchwaits > 21349917 2718532 80138637 103942631 694834 > > > onstat -g iov> > IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 > days 03:39:2 > 6 -- 2612224 Kbytes > > AIO I/O vps:> class/vp s io/s totalops dskread dskwrite dskcopy wakeups io/wup > errors > kio 0 s 116.6 51897068 49539166 2357902 0 98048287 > 0.5 0 > kio 1 i 111.2 49480269 46984299 2495970 0 93220077 > 0.5 0 > kio 2 s 30.4 13534186 12093534 1440652 0 24848841 > 0.5 0 > kio 3 s 63.5 28278503 26432019 1846484 0 52454339 > 0.5 0 > kio 4 i 14.9 6640466 5595584 1044882 0 12376862 > 0.5 0 > kio 5 i 20.4 9081038 7929376 1151662 0 16730461 > 0.5 0 > kio 6 s 45.1 20064775 18232398 1832377 0 36375647 > 0.6 0 > msc 0 i 0.9 396585 0 0 0 395863 > 1.0 0 > aio 0 i 0.5 216593 64458 20553 0 216504 > 1.0 0 > aio 1 i 0.0 127 30 2 0 194 > 0.7 0 > aio 2 i 0.0 9 5 0 0 14 > 0.6 0 > aio 3 i 0.0 10 4 0 0 6 > 1.7 0 > aio 4 i 0.0 8 1 0 0 4 > 2.0 0 > aio 5 i 0.0 7 1 0 0 4 > 1.8 0 > aio 6 i 0.0 4 1 0 0 3 > 1.3 0 > pio 0 i 0.0 0 0 0 0 1 > 0.0 0 > lio 0 i 0.0 0 0 0 0 1 > 0.0 0 > > db1:/ # onstat -R > > IBM Informix Dynamic Server Version 9.40.UC7 -- On-Line -- Up 5 > days 03:39:4 > 7 -- 2612224 Kbytes> > 128 buffer LRU queue sets priority levels > # type set total % of length LOW HIGH > 0 f 7031 99.8% 7020 6191 829 > 1 m 0.2% 11 2 9 > 2 f 7031 99.7% 7010 6200 810 > 3 m 0.3% 21 6 15 > 4 f 7031 99.7% 7012 6228 784 > 5 m 0.3% 19 4 15 > 6 f 7032 99.7% 7012 6174 838 > 7 m 0.3% 20 5 15 > 8 f 7031 99.7% 7013 6204 809 > 9 m 0.3% 18 3 15 > 10 f 7032 99.8% 7021 6193 828 > 11 m 0.2% 11 2 9 > 12 f 7031 99.7% 7008 6171 837 > 13 m 0.3% 23 4 19 > 14 f 7032 99.6% 7005 6146 859 > 15 m 0.4% 27 5 22 > 16 f 7031 99.6% 7003 6212 791 > 17 m 0.4% 28 5 23 > 18 f 7031 99.6% 7003 6171 832 > 19 m 0.4% 28 8 20 > 20 f 7031 99.6% 7003 6183 820 > 21 m 0.4% 28 5 23 > 22 f 7031 99.5% 6999 6181 818 > 23 m 0.5% 32 7 25 > 24 f 7031 99.7% 7013 6213 800 > 25 m 0.3% 18 6 12 > 26 f 7031 99.6% 7006 6211 795 > 27 m 0.4% 25 4 21 > 28 f 7031 99.8% 7015 6202 813 > 29 m 0.2% 16 8 8 > 30 f 7031 99.6% 7001 6156 845 > 31 m 0.4% 30 4 26 > 32 f 7031 99.5% 6999 6183 816 > 33 m 0.5% 32 7 25 > 34 f 7032 99.7% 7008 6225 783 > 35 m 0.3% 24 5 19 > 36 f 7032 99.7% 7011 6187 824 > 37 m 0.3% 21 4 17 > 38 f 7031 99.6% 7001 6157 844 > 39 m 0.4% 30 4 26 > 40 f 7032 99.5% 6995 6192 803 > 41 m 0.5% 37 11 26 > 42 f 7033 99.6% 7002 6145 857 > 43 m 0.4% 31 5 26 > 44 F 7030 99.7% 7010 6183 827 > 45 m 0.3% 20 5 15 > 46 f 7031 99.7% 7011 6214 797 > 47 m 0.3% 20 6 14 > 48 f 7031 99.7% 7013 6214 799 > 49 m 0.3% 18 3 15 > 50 f 7031 99.6% 7003 6216 787 > 51 m 0.4% 28 6 22 > 52 f 7032 99.7% 7014 6161 853 > 53 m 0.3% 18 3 15 > 54 f 7031 99.6% 7002 6206 796 > 55 m 0.4% 29 5 24 > 56 f 7031 99.5% 6996 6195 801 > 57 m 0.5% 35 9 26 > 58 f 7032 99.8% 7018 6215 803 > 59 m 0.2% 14 3 11 > 60 f 7031 99.7% 7012 6179 833 > 61 m 0.3% 19 3 16 > 62 f 7031 99.7% 7012 6217 795 > 63 m 0.3% 19 1 18 > 64 f

Besides seq scans: > > 228057060 779495368 2164074103 89.61 12488020 47951408 124371428 > > 91.10 % read cache is pretty low... this can be caused by sec scans too. Superboer.

Or excessive read ahead. Art On Tue, Jun 17, 2008 at 2:48 AM, Superboer <superboer7@t-online.de> wrote: > Besides seq scans: > > > > 228057060 779495368 2164074103 89.61 12488020 47951408 124371428 > > > 91.10 > > % read cache is pretty low... > this can be caused by sec scans too. > > > Superboer. > > > _______________________________________________ > Informix-list mailing list > Informix-list@iiug.org > http://www.iiug.org/mailman/listinfo/informix-list > -- Art S. Kagel Oninit (www.oninit.com) IIUG Board of Directors (art@iiug.org) Disclaimer: Please keep in mind that my own opinions are my own opinions and do not reflect on my employer, Oninit, the IIUG, nor any other organization with which I am associated either explicitly or implicitly. Neither do those opinions reflect those of other individuals affiliated with any entity with which I am affiliated nor those of the entities themselves.

Is there anything else I should be looking at? We have always had a large amount of seq scans. It's like a brick wall hit us, a normal query that takes 2 seconds is now taking 14 seconds. I checked the write back cache on the raid controllers and it's good. My CPU's (8) are 90% idle yet the speed is terrible. Here is a top output: load averages: 0.49, 0.38, 0.35 db1 13:15:42 90 processes: 88 sleeping, 1 stopped, 1 on cpu CPU states: 93.9% idle, 4.2% user, 1.9% kernel, 0.0% iowait, 0.0% swap Memory: 16.0G real, 12.7G free, 2.6G swap in use, 26.6G swap free PID USERNAME THR PR NCE SIZE RES STATE TIME FLTS CPU COMMAND 833 root 2 59 -10 2.5G 2.3G sleep 149:39 0 0.74% oninit 834 root 2 59 -10 2.5G 2.3G sleep 100:48 0 0.73% oninit 832 root 2 59 -10 2.5G 2.3G sleep 226:09 0 0.66% oninit 835 root 2 59 -10 2.5G 2.3G sleep 76:44 0 0.66% oninit 814 root 2 59 -10 2.5G 2.3G sleep 361:25 0 0.49% oninit 831 root 2 59 -10 2.5G 2.3G sleep 219:24 0 0.41% oninit 830 root 2 59 -10 2.5G 2.3G sleep 354:58 0 0.41% oninit 852 root 1 59 -10 2.5G 2.0G sleep 56:41 0 0.32% oninit 851 root 1 59 -10 2.5G 2.0G sleep 72:45 0 0.07% oninit 853 root 1 59 -10 2.5G 2.0G sleep 68:04 0 0.02% oninit 297 root 11 59 0 5520K 5088K sleep 3:13 0 0.00% picld 7129 root 1 59 0 2512K 1728K cpu01 0:00 0 0.00% top 839 root 1 59 -10 2.5G 2.0G sleep 0:29 0 0.00% oninit 893 root 1 59 0 4536K 2016K sleep 0:26 0 0.00% nmbd 441 root 20 59 0 3600K 3088K sleep 0:08 0 0.00% nscd

Gary Quiring wrote: > Is there anything else I should be looking at? We have always had a > large amount of seq scans. It's like a brick wall hit us, a normal > query that takes 2 seconds is now taking 14 seconds. I checked the > write back cache on the raid controllers and it's good. My CPU's (8) > are 90% idle yet the speed is terrible. Here is a top output: > > load averages: 0.49, 0.38, 0.35 db1 > 13:15:42 > 90 processes: 88 sleeping, 1 stopped, 1 on cpu > CPU states: 93.9% idle, 4.2% user, 1.9% kernel, 0.0% iowait, 0.0% > swap > Memory: 16.0G real, 12.7G free, 2.6G swap in use, 26.6G swap free > > PID USERNAME THR PR NCE SIZE RES STATE TIME FLTS CPU COMMAND > 833 root 2 59 -10 2.5G 2.3G sleep 149:39 0 0.74% oninit > 834 root 2 59 -10 2.5G 2.3G sleep 100:48 0 0.73% oninit > 832 root 2 59 -10 2.5G 2.3G sleep 226:09 0 0.66% oninit > 835 root 2 59 -10 2.5G 2.3G sleep 76:44 0 0.66% oninit > 814 root 2 59 -10 2.5G 2.3G sleep 361:25 0 0.49% oninit > 831 root 2 59 -10 2.5G 2.3G sleep 219:24 0 0.41% oninit > 830 root 2 59 -10 2.5G 2.3G sleep 354:58 0 0.41% oninit > 852 root 1 59 -10 2.5G 2.0G sleep 56:41 0 0.32% oninit > 851 root 1 59 -10 2.5G 2.0G sleep 72:45 0 0.07% oninit > 853 root 1 59 -10 2.5G 2.0G sleep 68:04 0 0.02% oninit > 297 root 11 59 0 5520K 5088K sleep 3:13 0 0.00% picld > 7129 root 1 59 0 2512K 1728K cpu01 0:00 0 0.00% top > 839 root 1 59 -10 2.5G 2.0G sleep 0:29 0 0.00% oninit > 893 root 1 59 0 4536K 2016K sleep 0:26 0 0.00% nmbd > 441 root 20 59 0 3600K 3088K sleep 0:08 0 0.00% nscd > > > The Priority and Nice values seem a bit odd, have these been set manually? Have you anything for AFFINITY or NOAGE?

On Jun 17, 2:32 pm, JJ <J...@Nothere.Co.Uk> wrote: > Gary Quiring wrote: > > Is there anything else I should be looking at?  We have always had a > > large amount of seq scans.  It's like a brick wall hit us, a normal > > query that takes 2 seconds is now taking 14 seconds.  I checked the > > write back cache on the raid controllers and it's good.  My CPU's (8) > > are 90% idle yet the speed is terrible.  Here is a top output: > > > load averages:  0.49,  0.38,  0.35                 db1 > > 13:15:42 > > 90 processes:  88 sleeping, 1 stopped, 1 on cpu > > CPU states: 93.9% idle,  4.2% user,  1.9% kernel,  0.0% iowait,  0.0% > > swap > > Memory: 16.0G real, 12.7G free, 2.6G swap in use, 26.6G swap free > > >   PID USERNAME THR PR NCE  SIZE   RES STATE   TIME FLTS    CPU COMMAND > >   833 root       2 59 -10  2.5G  2.3G sleep 149:39    0  0.74% oninit > >   834 root       2 59 -10  2.5G  2.3G sleep 100:48    0  0.73% oninit > >   832 root       2 59 -10  2.5G  2.3G sleep 226:09    0  0.66% oninit > >   835 root       2 59 -10  2.5G  2.3G sleep  76:44    0  0.66% oninit > >   814 root       2 59 -10  2.5G  2.3G sleep 361:25    0  0.49% oninit > >   831 root       2 59 -10  2.5G  2.3G sleep 219:24    0  0.41% oninit > >   830 root       2 59 -10  2.5G  2.3G sleep 354:58    0  0.41% oninit > >   852 root       1 59 -10  2.5G  2.0G sleep  56:41    0  0.32% oninit > >   851 root       1 59 -10  2.5G  2.0G sleep  72:45    0  0.07% oninit > >   853 root       1 59 -10  2.5G  2.0G sleep  68:04    0  0.02% oninit > >   297 root      11 59   0 5520K 5088K sleep   3:13    0  0.00% picld > >  7129 root       1 59   0 2512K 1728K cpu01   0:00    0  0.00% top > >   839 root       1 59 -10  2.5G  2.0G sleep   0:29    0  0.00% oninit > >   893 root       1 59   0 4536K 2016K sleep   0:26    0  0.00% nmbd > >   441 root      20 59   0 3600K 3088K sleep   0:08    0  0.00% nscd > > The Priority and Nice values seem a bit odd, have these been set manually? > > Have you anything for AFFINITY or NOAGE?- Hide quoted text - > > - Show quoted text - That is odd! I checked my other Solaris server and the output is very different on the Priority and Nice values: load averages: 1.40, 1.54, 1.55 emco7 14:49:42 66 processes: 63 sleeping, 1 stopped, 2 on cpu CPU states: 79.1% idle, 5.1% user, 15.8% kernel, 0.0% iowait, 0.0% swap Memory: 12.0G real, 9.2G free, 2.5G swap in use, 15.3G swap free PID USERNAME THR PR NCE SIZE RES STATE TIME FLTS CPU COMMAND 955 root 1 10 0 74.5M 7264K cpu06 51.8H 0 16.27% Xsun 722 root 2 39 0 2.4G 1.9G sleep 177:45 0 0.89% oninit 1040 root 2 55 0 2.4G 1.9G sleep 164:23 0 0.46% oninit 1046 root 2 59 0 2.4G 1.9G sleep 66:30 0 0.27% oninit 1240 root 1 49 0 2.4G 1.8G sleep 24:19 0 0.26% oninit 1047 root 2 59 0 2.4G 1.9G sleep 87:33 0 0.19% oninit 1233 root 1 59 0 2.4G 1.8G sleep 11:20 0 0.06% oninit 361 root 12 59 0 7632K 7208K sleep 5:03 0 0.05% picld 1234 root 1 59 0 2.4G 1.8G sleep 11:39 0 0.05% oninit 1049 root 2 49 0 2.4G 1.9G sleep 35:11 0 0.04% oninit 637 root 22 59 0 37.9M 22.6M sleep 0:51 0 0.01% java 10411 root 1 59 0 2504K 1736K cpu00 0:00 0 0.01% top 1602 root 1 59 0 3328K 2232K sleep 0:23 0 0.00% nmbd 12 root 1 59 0 9400K 8432K sleep 0:08 0 0.00% vxconfigd 415 root 12 59 0 24.8M 12.7M sleep 0:04 0 0.00% vxsvc I start oninit from rc.2. S99Informix Very simple script: #!/bin/sh INFORMIXDIR=/u/informix INFORMIXSERVER=db1 PATH=:$INFORMIXDIR/bin:$PATH ONCONFIG=onconfig.db1 export INFORMIXDIR INFORMIXSERVER PATH ONCONFIG cd /u/informix case "$1" in start) oninit ;; stop) onmode -ky ;; *) echo "Usage $0 {start|stop}" exit 1 ;;esac NOAGE 1 # Process aging AFF_SPROC 0 # Affinity start processor AFF_NPROCS 0 # Affinity number of processors

I am starting to think this is hardware. My ontape backup usually takes 2 1/2hours. Last night it took over 9 hours. I am seeing an unusually high amount of media errors on two ID's on a 3510 FC controller. I see media errors all the time but they don't last forever. Two drives are just constantly poking (every 2 seconds) the event log. It's odd because I thought the controller would decide the drive has too many issues and would take it off-line.

So far so good. I replaced the two drives earlier today and the speed came back to almost normal. I reviewed the event log on the other controller and found it also has constant events about media errors that started last night. We had a power outage over the weekend that must have spiked something. We never went down, the ups kept the server up but I have to assume the power must have caused these drives to suddenly create all these media errors. I want to thank everyone who helped with some Informix tuning suggestions. You guys are a great group. Thanks Gary Quiring