| Computers Forum Index » Computer - Databases - Informix » Delay in commands returning... |
|
Page 1 of 1 |
|
| Author |
Message |
| Neil Truby... |
 Posted: Wed Oct 21, 2009 10:26 pm |
|
|
|
Guest
|
Delay before resonding to commands.
On a certain server type (Sun M9000), and maybe others, I get about a
second's delay issuing any onstat command ... even onstat -m. See below,
took about one second.
On any other server - a Sun v890, a Linux server, it takes a few
millseconds.
I've tried a shared-memory rather than TCP/IP connection. No difference.
It doesn't seem to be causing any issue, I'm just curious ...
Thanks
Neil
*****************************************************************************
-bash-3.00$ time onstat -p
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
00:02:41 -- 25968640 Kbytes
Profile
dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits
%cached
7256 7738 161766 95.51 141 141 32
0.00
isamtot open start read write rewrite delete
commit rollbk
165785 8971 16332 54645 0 0 0
0 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 29.99 48.62 1 4
bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress
seqscans
0 0 127852 0 0 0 8
5
ixda-RA idx-RA da-RA RA-pgsused lchwaits
0 0 184 184 54368
real 0m1.027s
user 0m0.006s
sys 0m0.014s |
|
|
| Back to top |
|
|
|
| david at (no spam) smooth1.co.uk... |
| Posted: Wed Oct 21, 2009 10:26 pm |
|
|
|
Guest
|
On 21 Oct, 19:26, "Neil Truby" <neil.tr... at (no spam) ardenta.com> wrote:
Quote: Delay before resonding to commands.
On a certain server type (Sun M9000), and maybe others, I get about a
second's delay issuing any onstat command ... even onstat -m. See below,
took about one second.
On any other server - a Sun v890, a Linux server, it takes a few
millseconds.
I've tried a shared-memory rather than TCP/IP connection. No difference.
It doesn't seem to be causing any issue, I'm just curious ...
Thanks
Neil
*****************************************************************************
-bash-3.00$ time onstat -p
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
00:02:41 -- 25968640 Kbytes
Profile
dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits
%cached
7256 7738 161766 95.51 141 141 32
0.00
isamtot open start read write rewrite delete
commit rollbk
165785 8971 16332 54645 0 0 0
0 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 29.99 48.62 1 4
bufwaits lokwaits lockreqs deadlks dltouts ckpwaits compress
seqscans
0 0 127852 0 0 0 8
5
ixda-RA idx-RA da-RA RA-pgsused lchwaits
0 0 184 184 54368
real 0m1.027s
user 0m0.006s
sys 0m0.014s
Well onstat just attaches to shared memory so the connection type is
irrelevant.
What about "time onstat -" how long does that take??
Before hand do onstat -z then onstat -g spi afterwards, what latches
are taken?
Try truss -d onstat - where is the time taken?
onstat, at least for version 7 seems to open and close a lot of files
under $INFORMIXDIR/gls and $INFORMIXDIR/msg |
|
|
| Back to top |
|
|
|
| Fernando Nunes... |
| Posted: Thu Oct 22, 2009 1:39 am |
|
|
|
Guest
|
Neil Truby wrote:
Quote: Delay before resonding to commands.
On a certain server type (Sun M9000), and maybe others, I get about a
second's delay issuing any onstat command ... even onstat -m. See
below, took about one second.
On any other server - a Sun v890, a Linux server, it takes a few
millseconds.
I've tried a shared-memory rather than TCP/IP connection. No difference.
It doesn't seem to be causing any issue, I'm just curious ...
Thanks
Neil
*****************************************************************************
-bash-3.00$ time onstat -p
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
00:02:41 -- 25968640 Kbytes
Profile
dskreads pagreads bufreads %cached dskwrits pagwrits bufwrits
%cached
7256 7738 161766 95.51 141 141 32 0.00
isamtot open start read write rewrite delete
commit rollbk
165785 8971 16332 54645 0 0 0
0 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 29.99 48.62 1 4
bufwaits lokwaits lockreqs deadlks dltouts ckpwaits
compress seqscans
0 0 127852 0 0 0 8 5
ixda-RA idx-RA da-RA RA-pgsused lchwaits
0 0 184 184 54368
real 0m1.027s
user 0m0.006s
sys 0m0.014s
Do you have auditing turned on? I assume not, but just in case...?
Regards. |
|
|
| Back to top |
|
|
|
| david at (no spam) smooth1.co.uk... |
| Posted: Thu Oct 22, 2009 2:00 am |
|
|
|
Guest
|
On 22 Oct, 00:49, "Neil Truby" <neil.tr... at (no spam) ardenta.com> wrote:
Quote: "Andrew Clarke" <acla... at (no spam) civica.com.au> wrote in message
news:mailman.199.1256165950.6236.informix-list at (no spam) iiug.org...>> what about startup times of simple things like vi?
Ligthening-fast
Is it a machine difference? Longer $PATH or $LD_LIBRARY_PATH with more or
less to wade through?
-bash-3.00$ unset LD_LIBRARY_PATH
-bash-3.00$ time onstat -
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:42:58 -- 25968640 Kbytes
real 0m1.027s
user 0m0.006s
sys 0m0.013s
(No)
How many cpus on the host?
How many cpu vps configured?
What does iostat -x4 give?
What does vmstat 2 5 give?
What does top show for memory and cpu utilization?
Any errors in /var/log/messages or the online.log? |
|
|
| Back to top |
|
|
|
| Andrew Clarke... |
| Posted: Thu Oct 22, 2009 2:57 am |
|
|
|
Guest
|
what about startup times of simple things like vi? Is it a machine difference?
Longer $PATH or $LD_LIBRARY_PATH with more or less to wade through? OS
differences in the the implementation of "sticky" executables (ie retaining
the executable in memory on the off-chance it will be called again) or maybe
on one platform it's more expensive to attach to shared libraries; onstat
probably attaches to several while vi probably doesn't...
There's a process tracing tool that shows the system calls although the name
escapes me. You could probably use that to know which part of program startup
is taking the most time. |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Thu Oct 22, 2009 3:37 am |
|
|
|
Guest
|
<david at (no spam) smooth1.co.uk> wrote in message
news:74c11349-0684-4776-b3c3-bf3c4de63334 at (no spam) 33g2000vbe.googlegroups.com...
Quote: What about "time onstat -" how long does that take??
time onstat -
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:25:50 -- 25968640 Kbytes
real 0m1.022s
user 0m0.006s
sys 0m0.014s
Quote: Before hand do onstat -z then onstat -g spi afterwards, what latches
are taken?
-bash-3.00$ time onstat -z ; time onstat - ; time onstat -g spi
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:29:19 -- 25968640 Kbytes
real 0m3.049s
user 0m0.006s
sys 0m0.014s
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:29:22 -- 25968640 Kbytes
real 0m1.030s
user 0m0.006s
sys 0m0.017s
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:29:23 -- 25968640 Kbytes
Spin locks with waits:
Num Waits Num Loops Avg Loop/Wait Name
253 4161300 16447.83 mtcb sleeping_lock
1 209 209.00 vproc vp_lock, id = 5
2 2 1.00 vproc vp_lock, id = 6
1 44 44.00 vproc vp_lock, id = 8
1 1 1.00 vproc vp_lock, id = 9
2 247 123.50 vproc vp_lock, id = 15
1 1 1.00 vproc vp_lock, id = 18
1 38 38.00 vproc vp_lock, id = 19
1 49 49.00 vproc vp_lock, id = 22
1 3 3.00 vproc vp_lock, id = 23
4 1427 356.75 vproc vp_lock, id = 24
22 404 18.36 fast mutex, flush
real 0m8.362s
user 0m7.171s
sys 0m0.181s |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Thu Oct 22, 2009 3:38 am |
|
|
|
Guest
|
"Fernando Nunes" <domusonline at (no spam) gmail.com> wrote in message
news:hbnv39$q8m$1 at (no spam) news.eternal-september.org...
Quote:
Do you have auditing turned on? I assume not, but just in case...?
Regards.
no |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Thu Oct 22, 2009 3:49 am |
|
|
|
Guest
|
"Andrew Clarke" <aclarke at (no spam) civica.com.au> wrote in message
news:mailman.199.1256165950.6236.informix-list at (no spam) iiug.org...
Quote: what about startup times of simple things like vi?
Ligthening-fast
Is it a machine difference? Longer $PATH or $LD_LIBRARY_PATH with more or
less to wade through?
-bash-3.00$ unset LD_LIBRARY_PATH
-bash-3.00$ time onstat -
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
05:42:58 -- 25968640 Kbytes
real 0m1.027s
user 0m0.006s
sys 0m0.013s
(No) |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Thu Oct 22, 2009 7:47 pm |
|
|
|
Guest
|
<david at (no spam) smooth1.co.uk> wrote in message
news:620339bd-8d39-4d9c-8439-7bf7a541cd45 at (no spam) m11g2000vbl.googlegroups.com...
Quote: How many cpus on the host?
6 x quad-core SPARC VII+, each with 2 threads
Quote: How many cpu vps configured?
23
Quote: What does iostat -x4 give?
(below)
Quote: What does vmstat 2 5 give?
vmstat 2 5
kthr memory page disk faults cpu
r b w swap free re mf pi po fr de sr m1 m1 m1 m2 in sy cs us sy
id
0 0 0 52223776 43533320 79 690 16 4 4 0 5 1 1 1 16 7035 9286 9954 1 1
98
0 0 0 45136152 36143168 0 41 0 0 0 0 0 0 0 0 0 838 1192 1057 0 0
100
0 0 0 45135792 36142808 0 12 0 0 0 0 0 0 0 0 0 836 1576 1117 0 0
100
0 0 0 45135440 36142392 207 2017 0 0 0 0 0 0 0 0 0 948 3693 1262 0 0
100
0 0 0 45135792 36142792 0 0 0 0 0 0 0 0 0 0 0 833 1001 1050 0 0
100
Quote: What does top show for memory and cpu utilization?
top isn't a Solaris standard any more, more's the pity. Here's prstat:
PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
4098 root 5800K 3032K sleep 59 0 0:06:07 0.0% MultiNICBAgent/4
2661 root 2328K 1592K sleep 40 0 0:05:34 0.0% vvr_stats/1
422 daemon 4960K 2672K sleep 59 0 0:00:00 0.0% kcfd/5
1690 root 4144K 2256K sleep 59 0 0:00:00 0.0% syslogd/11
1657 root 1656K 1008K sleep 59 0 0:00:00 0.0% utmpd/1
1553 root 3320K 1424K sleep 59 0 0:00:00 0.0% cron/1
415 root 12M 8456K sleep 59 0 0:00:14 0.0% nscd/24
398 root 6408K 2800K sleep 59 0 0:00:01 0.0% syseventd/15
606 root 8624K 4312K sleep 59 0 0:00:04 0.0% vxesd/7
1547 root 1712K 688K sleep 59 0 0:00:00 0.0% efdaemon/1
421 root 4272K 2648K sleep 59 0 0:00:00 0.0% oplhpd/4
2871 root 2360K 1864K sleep 59 0 0:00:00 0.0% vxrelocd/1
418 root 6128K 5000K sleep 59 0 0:00:01 0.0% picld/6
374 root 3872K 848K sleep 59 0 0:00:02 0.0% ipmon/1
1682 root 2776K 1640K sleep 59 0 0:00:00 0.0% dcs/1
67 root 34M 31M sleep 59 0 0:52:44 0.0% vxconfigd/1
410 root 4936K 2664K sleep 59 0 0:00:07 0.0% devfsadm/6
23962 informix 25G 25G sleep 59 -10 1:33:16 0.0% oninit/2
1687 root 2368K 976K sleep 59 0 0:00:00 0.0% smcboot/1
9 root 10M 8800K sleep 59 0 0:00:07 0.0% svc.configd/15
7 root 32M 22M sleep 59 0 0:00:07 0.0% svc.startd/15
Total: 132 processes, 432 lwps, load averages: 0.14, 0.13, 0.14
Quote: Any errors in /var/log/messages or the online.log?
No.
This happens on multiple servers of this type, btw.
extended device statistics
device r/s w/s kr/s kw/s wait actv svc_t %w %b
md10 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md11 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md12 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md20 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md21 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md22 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md30 0.0 1.7 0.0 3.1 0.0 0.0 16.7 0 1
md31 0.0 1.7 0.0 3.1 0.0 0.0 16.6 0 1
md32 0.0 1.7 0.0 3.1 0.0 0.0 15.0 0 1
md40 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md41 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md42 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md50 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md51 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
md52 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
sd0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
sd1 0.0 1.7 0.0 3.1 0.0 0.0 16.6 0 1
sd2 0.0 1.7 0.0 3.1 0.0 0.0 15.0 0 1
sd3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd4 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd5 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd6 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd7 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd8 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd9 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd10 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd11 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd12 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd13 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd14 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd15 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd16 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd17 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd18 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd19 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd20 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd21 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd22 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd23 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd24 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd25 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd26 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd27 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd28 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd29 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd30 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd31 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd32 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd33 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd34 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd35 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd36 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd37 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd38 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd39 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd40 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd41 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd42 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd43 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd44 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd45 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd46 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd47 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd48 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd49 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd50 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
ssd51 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0
nfs1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0 0 |
|
|
| Back to top |
|
|
|
| Frank Langelage... |
| Posted: Fri Oct 23, 2009 12:13 am |
|
|
|
Guest
|
Neil Truby wrote:
Quote: Delay before resonding to commands.
On a certain server type (Sun M9000), and maybe others, I get about a
second's delay issuing any onstat command ... even onstat -m. See
below, took about one second.
On any other server - a Sun v890, a Linux server, it takes a few
millseconds.
I've tried a shared-memory rather than TCP/IP connection. No difference.
It doesn't seem to be causing any issue, I'm just curious ...
Thanks
Neil
As someone else already said, execute onstat through truss to get a
protocol of the system calls: truss -D -o /tmp/truss.out onstat -
The first column in /tmp/truss.out contains a float value representing
the time delta in seconds.
For more see "man truss".
Regards,
Frank |
|
|
| Back to top |
|
|
|
| LIGHT SCANS... |
| Posted: Mon Oct 26, 2009 8:14 pm |
|
|
|
Guest
|
Hello Neil,
I am going to guess that you allocated a large amount of your Sun
M9000's memory to Informix. It may take a second to read all that
memory (or even part of it) to give you an answer. Another guess is
that the many lines of Informix engine code interact with the many
lines of Sun operating system code causing a 1 second delay on a Sun
M9000. This maybe something you will have to live with or require
some Sun tuning.
Right or wrong, I am very curious of what you will eventually find
out.
-L.S. |
|
|
| Back to top |
|
|
|
| david at (no spam) smooth1.co.uk... |
| Posted: Mon Oct 26, 2009 10:31 pm |
|
|
|
Guest
|
On 26 Oct, 20:14, LIGHT SCANS <light_sc... at (no spam) yahoo.com> wrote:
Quote: Hello Neil,
I am going to guess that you allocated a large amount of your Sun
M9000's memory to Informix. It may take a second to read all that
memory (or even part of it) to give you an answer. Another guess is
that the many lines of Informix engine code interact with the many
lines of Sun operating system code causing a 1 second delay on a Sun
M9000. This maybe something you will have to live with or require
some Sun tuning.
Right or wrong, I am very curious of what you will eventually find
out.
-L.S.
Try running onstat -i then see how long command like p or s take to
return, it could be the time taken to attach to shared memory that is
the
problem. Also at least for version 7 onstat reads message files under
$INFORMIXDIR/msg and $INFORMIXDIR/gls and that can take time to
return.
Try the "truss -d onstat -" and what did that return?
david. |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Fri Oct 30, 2009 2:51 pm |
|
|
|
Guest
|
"LIGHT SCANS" <light_scans at (no spam) yahoo.com> wrote in message
news:0ab514e2-51f0-4f5d-8e42-03435920c006 at (no spam) z3g2000prd.googlegroups.com...
Quote: Hello Neil,
I am going to guess that you allocated a large amount of your Sun
M9000's memory to Informix. It may take a second to read all that
memory (or even part of it) to give you an answer. Another guess is
that the many lines of Informix engine code interact with the many
lines of Sun operating system code causing a 1 second delay on a Sun
M9000. This maybe something you will have to live with or require
some Sun tuning.
Right or wrong, I am very curious of what you will eventually find
out.
Plausible theory, and something I hadn't thought of testing. But, I tried
it on a small instance, and no difference:
time onstat -
IBM Informix Dynamic Server Version 10.00.FC9 -- On-Line -- Up
00:01:39 -- 361472 Kbytes
real 0m1.025s
user 0m0.006s
sys 0m0.013s |
|
|
| Back to top |
|
|
|
| Neil Truby... |
| Posted: Fri Oct 30, 2009 3:31 pm |
|
|
|
Guest
|
| I've raised a support call now btw, PMR 80853,001,866 refers. |
|
|
| Back to top |
|
|
|
|
