IDS 11.5FC6 on RHEL 5.3

Here's a starange one. When running SQL which interacts with OS to output
messages, it's very, very much slower at a new customer site than it is at
our own or others. The difference seems to be the AMD processors the
customer has (we have Intel) - the OS and IDS versions are identical.

Here's a a simple test case. Here's some SQL, which echoes out the message
"Hello World" 64 times:
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
....
!echo "Hello World"

Run it on the AMD server:

informix@db-1<qa1>:ardenta]$ time dbaccess sysmaster < crap5.sql

Database selected.

Hello World
....
Hello World

Database closed.


real 0m7.776s
user 0m0.016s
sys 0m0.049s

Run it on an Intel server, same IDS version etc:

Hello World
....
Hello World

Database closed.

real 0m0.580s
user 0m0.005s
sys 0m0.037s

12 times as slow on AMD. We noticed it when trunning some data load scripts
which outputs thousands of progress messages, and went from 10m at home to
50m on the client's (far superior) hardware. Of course we could just omit
the statements, but I am worried that this may be part of a bigger issue.

IBM PMR 85722,019,866 refers.

Console or Xwindows terminal? That could be a difference also. FWIW

Art

Art S. Kagel
Advanced DataTools (www.advancedatatools.com)
IIUG Board of Directors (art (AT) iiug (DOT) org)

See you at the 2010 IIUG Informix Conference
April 25-28, 2010
Overland Park (Kansas City), KS
www.iiug.org/conf

Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Advanced DataTools, the IIUG, nor any other
organization with which I am associated either explicitly, implicitly, or by
inference. Neither do those opinions reflect those of other individuals
affiliated with any entity with which I am affiliated nor those of the
entities themselves.



On Thu, Apr 15, 2010 at 6:03 PM, Neil Truby <neil.truby (AT) ardenta (DOT) com> wrote:

Just some usual suspects:

Misconfigured memory / mainboard parameters in BIOS?

Memory in a slow slot layout (running, but not wrong enough to cause an
error)? Or wrong speed?

Faulty Mainboard? Had this once, caused strange errors, including
intermittent speed behavior. Cause was a chipset chip with faulty
soldering.

Is a C/PERL/bash program also very slow, or only Informix programs?

My personal experience is that AMD // Intel do work more or less within
the same speed range, more problems occur with wrong memory and HD
layout or SAS/SCSI Controllers.

regards
Joerg Volz
------------------------------------------------------------------------
-----


-----Original Message-----
From: informix-list-bounces (AT) iiug (DOT) org
[mailto:informix-list-bounces (AT) iiug (DOT) org] On Behalf Of Neil Truby
Sent: Friday, April 16, 2010 12:04 AM
To: informix-list (AT) iiug (DOT) org
Subject: Slow OS calls on one chip type

IDS 11.5FC6 on RHEL 5.3

Here's a starange one. When running SQL which interacts with OS to
output
messages, it's very, very much slower at a new customer site than it is
at
our own or others. The difference seems to be the AMD processors the
customer has (we have Intel) - the OS and IDS versions are identical.

Here's a a simple test case. Here's some SQL, which echoes out the
message
"Hello World" 64 times:
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
....
!echo "Hello World"

Run it on the AMD server:

informix@db-1<qa1>:ardenta]$ time dbaccess sysmaster < crap5.sql

Database selected.

Hello World
....
Hello World

Database closed.


real 0m7.776s
user 0m0.016s
sys 0m0.049s

Run it on an Intel server, same IDS version etc:

Hello World
....
Hello World

Database closed.

real 0m0.580s
user 0m0.005s
sys 0m0.037s

12 times as slow on AMD. We noticed it when trunning some data load
scripts
which outputs thousands of progress messages, and went from 10m at home
to
50m on the client's (far superior) hardware. Of course we could just
omit
the statements, but I am worried that this may be part of a bigger
issue.

IBM PMR 85722,019,866 refers.

_______________________________________________
Informix-list mailing list
Informix-list (AT) iiug (DOT) org
http://www.iiug.org/mailman/listinfo/informix-list

IT Handel und Beratung Jorg Volz
Bernhard-Fruh-Str. 7
77855 Achern
GERMANY

Tel: +49 (0)7841-681651
Fax: +49 (0)7841-681654
Mobil: +49 (0)170-2989757

VAT-ID: DE201383541

http://www.it-volz.de

Joerg pretty much covered it.

Could also be the OS too. Depending on if its properly tuned. You can see some issues like this too.
__________________________________________________ _______________
Your E-mail and More On-the-Go. Get Windows Live Hotmail Free.
http://clk.atdmt.com/GBL/go/196390709/direct/01/

I'm using ssh via putty in each case.

"Joerg Volz" <joerg (AT) it-volz (DOT) de> wrote

Well I've tried it on two different physical servers at the customer site,
with the same result. So I certainly think a hardware error is unlikely.
It's possible that the same person systematically mis-configured the servers
on assembly.

I might have added that most Informix functions I've tried (dbimport, index
builds) are lightening fast on the AMDs. This system call is the only blip
i've found.

On 15 Apr, 23:54, "Neil Truby" <neil.tr... (AT) ardenta (DOT) com> wrote:

- Run a shell script with just the echos in and time that on both.

- Run top on both machines, do they have the same memory free?

- Run vmstat 2 5 and see if paging/swappiing is occuring.

- Run iostat -x 4 and check disk io times.

Otherwise strace the engine and see where it is taking the time ( my
memory is hazy but it could be the misc vp that spawning SYSTEM
calls).

I not sure if this can help , run:
$ strace -fc dbaccess sysmaster < crap5.sql

In both systems and compare what function exactly take more time ....
then you maybe have a way to discovery the reason.

César

--- Em qui, 15/4/10, Neil Truby <neil.truby (AT) ardenta (DOT) com> escreveu:

De: Neil Truby <neil.truby (AT) ardenta (DOT) com>
Assunto: Slow OS calls on one chip type
Para: informix-list (AT) iiug (DOT) org
Data: Quinta-feira, 15 de Abril de 2010, 19:03

IDS 11.5FC6 on RHEL 5.3

Here's a starange one.* When running SQL which interacts with OS to output
messages, it's very, very much slower at a new customer site than it is at
our own or others.* The difference seems to be the AMD processors the
customer has (we have Intel) - the OS and IDS versions are identical.

Here's a a simple test case.* Here's some SQL, which echoes out the message
"Hello World" 64 times:
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
!echo "Hello World"
....
!echo "Hello World"

Run it on the AMD server:

informix@db-1<qa1>:ardenta]$ time dbaccess sysmaster < crap5.sql

Database selected.

Hello World
....
Hello World

Database closed.


real* * 0m7.776s
user* * 0m0.016s
sys* ***0m0.049s

Run it on an Intel server, same IDS version etc:

Hello World
....
Hello World

Database closed.

real* * 0m0.580s
user* * 0m0.005s
sys* ***0m0.037s

12 times as slow on AMD.* We noticed it when trunning some data load scripts
which outputs thousands of progress messages, and went from 10m at home to
50m on the client's (far superior) hardware. Of course we could just omit
the statements, but I am worried that this may be part of a bigger issue.

IBM PMR 85722,019,866 refers.

_______________________________________________
Informix-list mailing list
Informix-list (AT) iiug (DOT) org
http://www.iiug.org/mailman/listinfo/informix-list

On 16/04/2010 14:08, Alexandre Marini wrote:
Well, why not do this (as previously posted, but removing the database connection) :

strace -o slow1.out -c -f dbaccess - slow1

where slow1 contains your 64 !echo "Hello World"

Also, just try it on the actual machine rather than via ssh

This is the output of strace -o slow1.out -fc dbaccess sysmaster <
crap5.sql :
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
88.47 0.415934 0 5760352 5759744 close
7.74 0.036405 560 65 execve
1.46 0.006865 107 64 clone
0.69 0.003256 2 1601 1058 open
0.39 0.001811 3 572 read
0.32 0.001496 1 1292 842 stat
0.26 0.001223 1 1072 mmap
0.10 0.000466 1 537 fstat
0.09 0.000443 1 452 rt_sigprocmask
0.09 0.000417 1 403 mprotect
0.09 0.000401 1 327 67 access
0.07 0.000327 2 196 brk
0.05 0.000241 2 141 munmap
0.04 0.000211 3 71 write
0.03 0.000128 2 64 setgid
0.02 0.000114 0 917 rt_sigaction
0.02 0.000072 1 64 setuid
0.01 0.000070 1 65 arch_prctl
0.01 0.000066 1 64 getppid
0.01 0.000055 0 132 uname
0.01 0.000050 0 132 getuid
0.01 0.000043 1 64 getpid
0.01 0.000039 0 284 lseek
0.00 0.000000 0 68 67 ioctl
0.00 0.000000 0 1 shmat
0.00 0.000000 0 2 socket
0.00 0.000000 0 2 2 connect
0.00 0.000000 0 64 64 getpeername
0.00 0.000000 0 64 64 wait4
0.00 0.000000 0 25 semop
0.00 0.000000 0 1 semctl
0.00 0.000000 0 1 shmdt
0.00 0.000000 0 8 fcntl
0.00 0.000000 0 1 getcwd
0.00 0.000000 0 1 readlink
0.00 0.000000 0 66 getrlimit
0.00 0.000000 0 129 getgid
0.00 0.000000 0 64 geteuid
0.00 0.000000 0 64 getegid
0.00 0.000000 0 64 getpgrp
0.00 0.000000 0 1 setrlimit
0.00 0.000000 0 2 futex
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 0.470133 5769561 5761908 total

And the output of strace -o slow2.out -c -f dbaccess - crap5.sql:
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
98.20 23.093423 360835 64 wait4
1.47 0.346367 0 5760348 5759680 close
0.23 0.054686 841 65 execve
0.02 0.005324 83 64 clone
0.02 0.004632 3 1597 1058 open
0.01 0.002853 5 562 read
0.01 0.002439 2 1070 mmap
0.01 0.001597 1 1292 842 stat
0.00 0.000942 2 403 mprotect
0.00 0.000836 1 790 rt_sigaction
0.00 0.000502 8 64 write
0.00 0.000481 1 325 66 access
0.00 0.000417 2 265 lseek
0.00 0.000341 1 535 fstat
0.00 0.000309 1 387 rt_sigprocmask
0.00 0.000237 2 140 munmap
0.00 0.000182 1 129 uname
0.00 0.000118 1 128 getuid
0.00 0.000118 2 64 setgid
0.00 0.000115 2 64 geteuid
0.00 0.000090 1 65 arch_prctl
0.00 0.000079 1 64 setuid
0.00 0.000075 1 64 getpid
0.00 0.000071 1 64 getppid
0.00 0.000009 0 66 getrlimit
0.00 0.000000 0 196 brk
0.00 0.000000 0 1 ioctl
0.00 0.000000 0 3 alarm
0.00 0.000000 0 2 socket
0.00 0.000000 0 2 2 connect
0.00 0.000000 0 64 64 getpeername
0.00 0.000000 0 10 fcntl
0.00 0.000000 0 1 readlink
0.00 0.000000 0 128 getgid
0.00 0.000000 0 64 getegid
0.00 0.000000 0 64 getpgrp
0.00 0.000000 0 1 setrlimit
0.00 0.000000 0 2 futex
0.00 0.000000 0 1 set_tid_address
0.00 0.000000 0 1 set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00 23.516243 5769219 5761712 total