Re: Slow OS calls on one chip type
Posted in 2010
Topics: Server Administration
> 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
I'm not expert in C so, I just can provide a little more information to you:
About wait4 : http://www.unix.com/apropos-man/All/0/wait4/
To identify who is calling this function, run replacing the -c to -r on strace.
I not sure, but I believed there some environment set , like LD_LIBRARY , LD_PRELOAD what force the BSD library first in the path... but this is just a guess, some developer expert or linux suport maybe can give some light...
try compare the env / set output of the two environment...
but this is just shooting in the dark
Regards
César
--- Em seg, 3/5/10, Neil Truby <neil.truby@ardenta.com> escreveu:
De: Neil Truby <neil.truby@ardenta.com>
Assunto: Re: Slow OS calls on one chip type
Para: informix-list@iiug.org
Data: Segunda-feira, 3 de Maio de 2010, 16:40
> 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
_______________________________________________
Informix-list mailing list
Informix-list@iiug.org
http://www.iiug.org/mailman/listinfo/informix-list