SEO

Our product uses distributed computing to share load among various
servers.
The main server receices requests for client and dispatches them to
the worker server for doing the actual work.

The main server does connection pooling with the worker server to
avoid recreating the connection.

We see very high kernel time when we reuse the same connection.

However, if we close the connection after every request to the worker
server and that forces it ot open new connection for every request
than the main server show very low kernel time.

This kernel time avoids us from pushing the main server to receive
more request even when the total cpu usage is only 60%


Any tool we would use to figure out the reason for the high kernel
time.

Do we need to set any socket option.

Any Suggestins why that would happen.

It happens on HP-UX 11.00 and 11i

When you reuse connections, do you see more work being done?

You might consider using prospect (I think there is a copy on the dspp
site, if not, then ftp.cup.hp.com under dist/networking/tools/) to get
a combined profile of your application and the kernel at the same
time.

rick jones
--
oxymoron n, commuter in a gas-guzzling luxury SUV with an American flag
these opinions are mine, all mine; HP might not want them anyway...
feel free to post, OR email to raj in cup.hp.com but NOT BOTH...

Our System has 4 CPUs.
If we reuse the connection, the throughput drastically drops. As all
CPUs cannot be fully utilize.

However, if open a new connection for each communication. Then I can
max out the CPUs and throughput is much better.

So No, if we reuse the connection less work is actually done.

I will try to run prospect.

Thanks For the help.

Rick Jones <foo@bar.baz.invalid> wrote in message news:<j3mNb.12394$qA4.7257@news.cpqcorp.net>...
> When you reuse connections, do you see more work being done?
>
> You might consider using prospect (I think there is a copy on the dspp
> site, if not, then ftp.cup.hp.com under dist/networking/tools/) to get
> a combined profile of your application and the kernel at the same
> time.
>
> rick jones

The output from prospect is attached below for both the cases
1. When the connection is closed right away after every request.
2. If the connection is polled, however, since http 1.0 is used the
other end closes the connection and this node determines that when
reusing the socket and verifies that its already closed.

My Cluster is made up of HP-UX node which does the forwarding and
windows nodes which does the actual work of processing the data and
stuff. I am concerned about the HP node, which takes up too much
kernel time in CASE 2 described above.

================================================== ===========================
The prospect output when the socket kept open so that it can be
reused....


encycsrvr7 (07388)NM Birth (pre-exist) ps:=
(/actu01/ibondre/DEV040120/AcServer/bin/encycs
rvr7 -Spmd -Q81)
Process did not END - use last SLEEP

First execution after benchmark start = -0.000 Seconds

KI Elapsed Time = 60.023909 100.000% Total
KTC Elapsed Time = 196.386652 327.181% Total
KTC Run Time = 60.068209 30.587%
KTC Not Charged Time = 136.318444 69.413%

Sorted List of SPUs Used for this Process: [(0:41%), (3:22%), (2:21%),
(1:15%)]

-------------------------------------------------------------------------------
Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
EPB
-------------------------------------------------------------------------------
Clock Type Seconds % Elapsed uSec/Count
Counts

ELAPSED TOTAL 60.068209 100.000% Total
EXECUTION TOTAL 57.401422 95.560% Total
Execution Sys 29.720966 49.479% 83.7
355107
Execution UseR 19.771522 32.915% 14.6
1350200
Execution CsW 3.099385 5.160% 3.2
960013
BLOCKED TOTAL 2.666787 4.440% 844.7
3157
Execution IntSys 2.589765 4.311% 94.2
27498
Blocked misc 2.164232 3.603% 1372.4
1577
Execution IntUseR 2.155384 3.588% 75.4
28568
Blocked PreempT 0.502555 0.837% 318.1
1580
Execution TraP 0.063200 0.105% 9.7
6503
Execution VfaulT 0.001200 0.002% 133.4
9

-------------------------------------------------------------------------------
Section 1.1: Time Process Executed during System Calls
-------------------------------------------------------------------------------
TOTAL Sys 29.720966 100.000% 83.7
355107
write Sys 2.792251 9.395% 14.0
199533
read Sys 1.695414 5.704% 39.4
43019
poll Sys 1.157552 3.895% 19.5
59297
close Sys 0.559656 1.883% 103.7
5398
accept Sys 0.535603 1.802% 99.1
5407
lwp_create Sys 0.226134 0.761% 41.8
5407
lwp_detached_exit Sys 0.144207 0.485% 26.7
5392
recv Sys 0.132989 0.447% 12.3
10816
ioctl Sys 0.098347 0.331% 9.1
10814
gettimeofday Sys 0.063984 0.215% 5.8
10966
sched_yield Sys 0.055425 0.186% 18.6
2973
ksleep Sys 0.016261 0.055% 43.2
376
kwakeup Sys 0.006200 0.021% 30.5
203
time Sys 0.004303 0.014% 6.8
637
sigtimedwait Sys 0.002511 0.008% 33.9
74
clock_gettime Sys 0.001374 0.005% 8.2
167
- Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.2: Time Process Preempted in System Calls
-------------------------------------------------------------------------------
TOTAL PreempT 0.502555 100.000% 318.1
1580
poll PreempT 0.232173 46.199% 240.6
965
recv PreempT 0.179577 35.733% 1026.2
175
write PreempT 0.025858 5.145% 114.9
225
kwakeup PreempT 0.017337 3.450% 4334.2
4
read PreempT 0.016161 3.216% 256.5
63
ioctl PreempT 0.013858 2.757% 533.0
26
sigtimedwait PreempT 0.004531 0.902% 453.1
10
gettimeofday PreempT 0.003971 0.790% 152.7
26
lwp_create PreempT 0.003628 0.722% 181.4
20
ksleep PreempT 0.001939 0.386% 121.2
16
close PreempT 0.001631 0.325% 81.6
20
- Skip remainder, SPU of 0.0008 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.3: Time Process Blocked
-------------------------------------------------------------------------------
TOTAL BlockeD 2.666787 100.000% 844.7
3157
poll BlockeD 2.002994 75.109% 2101.8
953
Preempt PreempT 0.502555 18.845% 318.1
1580
recv BlockeD 0.068728 2.577% 384.0
179
write BlockeD 0.046070 1.728% 202.1
228
ksleep BlockeD 0.034905 1.309% 2181.6
16
ioctl BlockeD 0.014497 0.544% 536.9
27
sigtimedwait BlockeD 0.013226 0.496% 1322.6
10
accept BlockeD 0.004590 0.172% 327.8
14
- Skip remainder, SPU of 0.0010 is below '-m 0.0010' Sec




================================================== ===========================
================================================== ===========================
The prospect output when the socket is closed after every request is
as follows.


encycsrvr7 (07410)NM Birth (pre-exist) ps:=
(/actu01/ibondre/DEV040120/AcServer/bin/encycs
rvr7 -Spmd -Q81)
Process did not END - use last SLEEP

First execution after benchmark start = 0.003 Seconds

KI Elapsed Time = 60.003979 100.000% Total
KTC Elapsed Time = 217.871878 363.096% Total
KTC Run Time = 27.716669 12.722%
KTC Not Charged Time = 190.155208 87.278%

Sorted List of SPUs Used for this Process: [(2:26%), (0:25%), (1:25%),
(3:24%)]

-------------------------------------------------------------------------------
Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
EPB
-------------------------------------------------------------------------------
Clock Type Seconds % Elapsed uSec/Count
Counts

ELAPSED TOTAL 27.716669 100.000% Total
EXECUTION TOTAL 25.600633 92.365% Total
Execution UseR 18.064501 65.176% 38.9
464853
Execution Sys 6.038643 21.787% 16.4
367401
BLOCKED TOTAL 2.116037 7.635% 1284.0
1648
Blocked misc 2.031626 7.330% 2486.7
817
Execution IntUseR 0.993137 3.583% 32.8
30318
Execution IntSys 0.269954 0.974% 22.7
11870
Execution CsW 0.225448 0.813% 3.4
66172
Blocked PreempT 0.084410 0.305% 101.6
831
Execution TraP 0.006501 0.023% 6.9
945
Execution VfaulT 0.002450 0.009% 144.1
17

-------------------------------------------------------------------------------
Section 1.1: Time Process Executed during System Calls
-------------------------------------------------------------------------------
TOTAL Sys 6.038643 100.000% 16.4
367401
write Sys 1.858111 30.770% 10.0
186610
poll Sys 0.863837 14.305% 13.2
65285
read Sys 0.780819 12.930% 15.7
49699
close Sys 0.763243 12.639% 73.8
10343
accept Sys 0.398319 6.596% 77.1
5165
socket Sys 0.396285 6.562% 76.7
5167
connect Sys 0.336425 5.571% 65.1
5167
lwp_create Sys 0.171709 2.843% 33.2
5165
setsockopt Sys 0.127257 2.107% 24.6
5165
lwp_detached_exit Sys 0.106290 1.760% 20.6
5170
recv Sys 0.103426 1.713% 20.0
5166
gettimeofday Sys 0.054678 0.905% 5.2
10502
sched_yield Sys 0.042005 0.696% 17.6
2384
time Sys 0.035094 0.581% 3.2
10962
ksleep Sys 0.010853 0.180% 40.5
268
kwakeup Sys 0.003401 0.056% 32.7
104
sigtimedwait Sys 0.001524 0.025% 20.9
73
clock_gettime Sys 0.001089 0.018% 6.5
167
- Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.2: Time Process Preempted in System Calls
-------------------------------------------------------------------------------
TOTAL PreempT 0.084410 100.000% 101.6
831
recv PreempT 0.038530 45.646% 458.7
84
poll PreempT 0.038076 45.108% 62.4
610
read PreempT 0.002635 3.122% 90.9
29
connect PreempT 0.001419 1.681% 67.6
21
write PreempT 0.001276 1.512% 24.5
52
- Skip remainder, SPU of 0.0006 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.3: Time Process Blocked
-------------------------------------------------------------------------------
TOTAL BlockeD 2.116037 100.000% 1284.0
1648
poll BlockeD 1.744862 82.459% 2917.8
598
recv BlockeD 0.136402 6.446% 1684.0
81
Preempt PreempT 0.084410 3.989% 101.6
831
write BlockeD 0.046357 2.191% 874.7
53
read BlockeD 0.037055 1.751% 1235.2
30
sigtimedwait BlockeD 0.026671 1.260% 13335.6
2
connect BlockeD 0.025623 1.211% 1220.2
21
ksleep BlockeD 0.011171 0.528% 1861.8
6
lwp_create BlockeD 0.001687 0.080% 843.3
2
time BlockeD 0.001244 0.059% 177.7
7
- Skip remainder, SPU of 0.0004 is below '-m 0.0010' Sec

Irfan Bondre <ibondre@yahoo.com> wrote:
> The output from prospect is attached below for both the cases
> 1. When the connection is closed right away after every request.
> 2. If the connection is polled, however, since http 1.0 is used the
> other end closes the connection and this node determines that when
> reusing the socket and verifies that its already closed.

Indeed, if this is only ever going to be HTTP 1.0 without keepalives,
there is little point to keeping the connection open. When you said
earlier that you kept the connection open, I thought it was going to
be doing useful work.

If indeed, in case 2, there is no useful work to be done on the
connection after the first and only query, all it will be doing is
adding another FD to the list of FD's being polled (I'm assuming you
have multiple connections open at once?), and you will indeed have to
have stuff going up to the user when the remote closes the connection.

rick jones
--
portable adj, code that compiles under more than one compiler
these opinions are mine, all mine; HP might not want them anyway...
feel free to post, OR email to raj in cup.hp.com but NOT BOTH...

Oops, I made a mistake in my last question?

Also we have multiple connections open between the two nodes.

Yes, we use http 1.0 between the two nodes, but We have hacked the
code to not close the connection and hence do real connection pooling.

Sorry for the confusion.

So to repeat the previous details....



The output from prospect is attached below for both the cases
1. When the connection is closed right away after every request.
2. If the connection is polled. We pool the connection.

My Cluster is made up of HP-UX node which does the forwarding and
windows nodes which does the actual work of processing the data and
stuff. I am concerned about the HP node, which takes up too much
kernel time in CASE 2 described above.

================================================== ===========================
The prospect output when the socket kept open so that it can be
reused....


encycsrvr7 (07388)NM Birth (pre-exist) ps:=
(/actu01/ibondre/DEV040120/AcServer/bin/encycs
rvr7 -Spmd -Q81)
Process did not END - use last SLEEP

First execution after benchmark start = -0.000 Seconds

KI Elapsed Time = 60.023909 100.000% Total
KTC Elapsed Time = 196.386652 327.181% Total
KTC Run Time = 60.068209 30.587%
KTC Not Charged Time = 136.318444 69.413%

Sorted List of SPUs Used for this Process: [(0:41%), (3:22%), (2:21%),
(1:15%)]

-------------------------------------------------------------------------------
Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
EPB
-------------------------------------------------------------------------------
Clock Type Seconds % Elapsed uSec/Count
Counts

ELAPSED TOTAL 60.068209 100.000% Total
EXECUTION TOTAL 57.401422 95.560% Total
Execution Sys 29.720966 49.479% 83.7
355107
Execution UseR 19.771522 32.915% 14.6
1350200
Execution CsW 3.099385 5.160% 3.2
960013
BLOCKED TOTAL 2.666787 4.440% 844.7
3157
Execution IntSys 2.589765 4.311% 94.2
27498
Blocked misc 2.164232 3.603% 1372.4
1577
Execution IntUseR 2.155384 3.588% 75.4
28568
Blocked PreempT 0.502555 0.837% 318.1
1580
Execution TraP 0.063200 0.105% 9.7
6503
Execution VfaulT 0.001200 0.002% 133.4
9

-------------------------------------------------------------------------------
Section 1.1: Time Process Executed during System Calls
-------------------------------------------------------------------------------
TOTAL Sys 29.720966 100.000% 83.7
355107
write Sys 2.792251 9.395% 14.0
199533
read Sys 1.695414 5.704% 39.4
43019
poll Sys 1.157552 3.895% 19.5
59297
close Sys 0.559656 1.883% 103.7
5398
accept Sys 0.535603 1.802% 99.1
5407
lwp_create Sys 0.226134 0.761% 41.8
5407
lwp_detached_exit Sys 0.144207 0.485% 26.7
5392
recv Sys 0.132989 0.447% 12.3
10816
ioctl Sys 0.098347 0.331% 9.1
10814
gettimeofday Sys 0.063984 0.215% 5.8
10966
sched_yield Sys 0.055425 0.186% 18.6
2973
ksleep Sys 0.016261 0.055% 43.2
376
kwakeup Sys 0.006200 0.021% 30.5
203
time Sys 0.004303 0.014% 6.8
637
sigtimedwait Sys 0.002511 0.008% 33.9
74
clock_gettime Sys 0.001374 0.005% 8.2
167
- Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.2: Time Process Preempted in System Calls
-------------------------------------------------------------------------------
TOTAL PreempT 0.502555 100.000% 318.1
1580
poll PreempT 0.232173 46.199% 240.6
965
recv PreempT 0.179577 35.733% 1026.2
175
write PreempT 0.025858 5.145% 114.9
225
kwakeup PreempT 0.017337 3.450% 4334.2
4
read PreempT 0.016161 3.216% 256.5
63
ioctl PreempT 0.013858 2.757% 533.0
26
sigtimedwait PreempT 0.004531 0.902% 453.1
10
gettimeofday PreempT 0.003971 0.790% 152.7
26
lwp_create PreempT 0.003628 0.722% 181.4
20
ksleep PreempT 0.001939 0.386% 121.2
16
close PreempT 0.001631 0.325% 81.6
20
- Skip remainder, SPU of 0.0008 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.3: Time Process Blocked
-------------------------------------------------------------------------------
TOTAL BlockeD 2.666787 100.000% 844.7
3157
poll BlockeD 2.002994 75.109% 2101.8
953
Preempt PreempT 0.502555 18.845% 318.1
1580
recv BlockeD 0.068728 2.577% 384.0
179
write BlockeD 0.046070 1.728% 202.1
228
ksleep BlockeD 0.034905 1.309% 2181.6
16
ioctl BlockeD 0.014497 0.544% 536.9
27
sigtimedwait BlockeD 0.013226 0.496% 1322.6
10
accept BlockeD 0.004590 0.172% 327.8
14
- Skip remainder, SPU of 0.0010 is below '-m 0.0010' Sec




================================================== ===========================
================================================== ===========================
The prospect output when the socket is closed after every request is
as follows.


encycsrvr7 (07410)NM Birth (pre-exist) ps:=
(/actu01/ibondre/DEV040120/AcServer/bin/encycs
rvr7 -Spmd -Q81)
Process did not END - use last SLEEP

First execution after benchmark start = 0.003 Seconds

KI Elapsed Time = 60.003979 100.000% Total
KTC Elapsed Time = 217.871878 363.096% Total
KTC Run Time = 27.716669 12.722%
KTC Not Charged Time = 190.155208 87.278%

Sorted List of SPUs Used for this Process: [(2:26%), (0:25%), (1:25%),
(3:24%)]

-------------------------------------------------------------------------------
Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
EPB
-------------------------------------------------------------------------------
Clock Type Seconds % Elapsed uSec/Count
Counts

ELAPSED TOTAL 27.716669 100.000% Total
EXECUTION TOTAL 25.600633 92.365% Total
Execution UseR 18.064501 65.176% 38.9
464853
Execution Sys 6.038643 21.787% 16.4
367401
BLOCKED TOTAL 2.116037 7.635% 1284.0
1648
Blocked misc 2.031626 7.330% 2486.7
817
Execution IntUseR 0.993137 3.583% 32.8
30318
Execution IntSys 0.269954 0.974% 22.7
11870
Execution CsW 0.225448 0.813% 3.4
66172
Blocked PreempT 0.084410 0.305% 101.6
831
Execution TraP 0.006501 0.023% 6.9
945
Execution VfaulT 0.002450 0.009% 144.1
17

-------------------------------------------------------------------------------
Section 1.1: Time Process Executed during System Calls
-------------------------------------------------------------------------------
TOTAL Sys 6.038643 100.000% 16.4
367401
write Sys 1.858111 30.770% 10.0
186610
poll Sys 0.863837 14.305% 13.2
65285
read Sys 0.780819 12.930% 15.7
49699
close Sys 0.763243 12.639% 73.8
10343
accept Sys 0.398319 6.596% 77.1
5165
socket Sys 0.396285 6.562% 76.7
5167
connect Sys 0.336425 5.571% 65.1
5167
lwp_create Sys 0.171709 2.843% 33.2
5165
setsockopt Sys 0.127257 2.107% 24.6
5165
lwp_detached_exit Sys 0.106290 1.760% 20.6
5170
recv Sys 0.103426 1.713% 20.0
5166
gettimeofday Sys 0.054678 0.905% 5.2
10502
sched_yield Sys 0.042005 0.696% 17.6
2384
time Sys 0.035094 0.581% 3.2
10962
ksleep Sys 0.010853 0.180% 40.5
268
kwakeup Sys 0.003401 0.056% 32.7
104
sigtimedwait Sys 0.001524 0.025% 20.9
73
clock_gettime Sys 0.001089 0.018% 6.5
167
- Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.2: Time Process Preempted in System Calls
-------------------------------------------------------------------------------
TOTAL PreempT 0.084410 100.000% 101.6
831
recv PreempT 0.038530 45.646% 458.7
84
poll PreempT 0.038076 45.108% 62.4
610
read PreempT 0.002635 3.122% 90.9
29
connect PreempT 0.001419 1.681% 67.6
21
write PreempT 0.001276 1.512% 24.5
52
- Skip remainder, SPU of 0.0006 is below '-m 0.0010' Sec

-------------------------------------------------------------------------------
Section 1.3: Time Process Blocked
-------------------------------------------------------------------------------
TOTAL BlockeD 2.116037 100.000% 1284.0
1648
poll BlockeD 1.744862 82.459% 2917.8
598
recv BlockeD 0.136402 6.446% 1684.0
81
Preempt PreempT 0.084410 3.989% 101.6
831
write BlockeD 0.046357 2.191% 874.7
53
read BlockeD 0.037055 1.751% 1235.2
30
sigtimedwait BlockeD 0.026671 1.260% 13335.6
2
connect BlockeD 0.025623 1.211% 1220.2
21
ksleep BlockeD 0.011171 0.528% 1861.8
6
lwp_create BlockeD 0.001687 0.080% 843.3
2
time BlockeD 0.001244 0.059% 177.7
7
- Skip remainder, SPU of 0.0004 is below '-m 0.0010' Sec

Irfan Bondre <ibondre@yahoo.com> wrote:
> Oops, I made a mistake in my last question?

> Also we have multiple connections open between the two nodes.

> Yes, we use http 1.0 between the two nodes, but We have hacked the
> code to not close the connection and hence do real connection pooling.

> Sorry for the confusion.

> So to repeat the previous details....



> The output from prospect is attached below for both the cases

BTW, I thought there was a mode in prospect that would give a simple
kernel profile - if that is the case, such a profile may be quite
helpful.

> 1. When the connection is closed right away after every request.
> 2. If the connection is polled. We pool the connection.

> My Cluster is made up of HP-UX node which does the forwarding and
> windows nodes which does the actual work of processing the data and
> stuff. I am concerned about the HP node, which takes up too much
> kernel time in CASE 2 described above.

OK, so there are sockets between the HP-UX and Windows systems that
are used for forwarding work, and then there are sockets between the
HP-UX and other systems on which requests arrive. Is that correct?

And then in case two, where the socket is kept open, you mean the
socket between the HP-UX and and the Windows compute servers yes?

> ================================================== ===========================
> The prospect output when the socket kept open so that it can be
> reused....


> encycsrvr7 (07388)NM Birth (pre-exist) ps:=
> (/actu01/ibondre/DEV040120/AcServer/bin/encycs
> rvr7 -Spmd -Q81)
> Process did not END - use last SLEEP

> First execution after benchmark start = -0.000 Seconds

> KI Elapsed Time = 60.023909 100.000% Total
> KTC Elapsed Time = 196.386652 327.181% Total
> KTC Run Time = 60.068209 30.587%
> KTC Not Charged Time = 136.318444 69.413%

> Sorted List of SPUs Used for this Process: [(0:41%), (3:22%), (2:21%),
> (1:15%)]

> -------------------------------------------------------------------------------
> Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
> EPB
> -------------------------------------------------------------------------------
> Clock Type Seconds % Elapsed uSec/Count
> Counts

> ELAPSED TOTAL 60.068209 100.000% Total
> EXECUTION TOTAL 57.401422 95.560% Total
> Execution Sys 29.720966 49.479% 83.7
> 355107
> Execution UseR 19.771522 32.915% 14.6
> 1350200
> Execution CsW 3.099385 5.160% 3.2
> 960013
> BLOCKED TOTAL 2.666787 4.440% 844.7
> 3157
> Execution IntSys 2.589765 4.311% 94.2
> 27498
> Blocked misc 2.164232 3.603% 1372.4
> 1577
> Execution IntUseR 2.155384 3.588% 75.4
> 28568
> Blocked PreempT 0.502555 0.837% 318.1
> 1580
> Execution TraP 0.063200 0.105% 9.7
> 6503
> Execution VfaulT 0.001200 0.002% 133.4
> 9

> -------------------------------------------------------------------------------
> Section 1.1: Time Process Executed during System Calls
> -------------------------------------------------------------------------------
> TOTAL Sys 29.720966 100.000% 83.7
> 355107
> write Sys 2.792251 9.395% 14.0
> 199533
> read Sys 1.695414 5.704% 39.4
> 43019
> poll Sys 1.157552 3.895% 19.5
> 59297
> close Sys 0.559656 1.883% 103.7
> 5398
> accept Sys 0.535603 1.802% 99.1
> 5407

I find it interesting that there would be soooo many write calls for
only ~5400 connections. Something on the order of 37 calls to write
for each connection. Does that sound right to you based on how the
app should work? How much data is being transfered here?

It is also interesting to me that there would be 10X the number of
poll calls as there are accepts(). A tusc trace would show roughly
how many fds are being polled each time.

ftp://ftp.cup.hp.com/dist/networking...eventports.txt

> lwp_create Sys 0.226134 0.761% 41.8
> 5407
> lwp_detached_exit Sys 0.144207 0.485% 26.7
> 5392

I take it you are creating and destroying threads on the fly?

> recv Sys 0.132989 0.447% 12.3
> 10816
> ioctl Sys 0.098347 0.331% 9.1
> 10814
> gettimeofday Sys 0.063984 0.215% 5.8
> 10966

If the gettimeofday calls are just for measuring time deltas, HP-UX
(might need some patches) has a gethrtime() call these days.

> sched_yield Sys 0.055425 0.186% 18.6
> 2973
> ksleep Sys 0.016261 0.055% 43.2
> 376
> kwakeup Sys 0.006200 0.021% 30.5
> 203

Sched_yield in conjunction with ksleep and kwakeup are indications of
possible mutex contention in an application. If you take a tusc trace
(have it include lwpids in the output) the arguments to ksleep/kwakeup
can point to the mutex(es) in question. Of course at this low
percentage of time it proibably isnt a big deal, but if/when you try
to scale this up, it may become an issue.

> time Sys 0.004303 0.014% 6.8
> 637
> sigtimedwait Sys 0.002511 0.008% 33.9
> 74
> clock_gettime Sys 0.001374 0.005% 8.2
> 167
> - Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

> -------------------------------------------------------------------------------
> Section 1.2: Time Process Preempted in System Calls
> -------------------------------------------------------------------------------
> TOTAL PreempT 0.502555 100.000% 318.1
> 1580
> poll PreempT 0.232173 46.199% 240.6
> 965
> recv PreempT 0.179577 35.733% 1026.2
> 175
> write PreempT 0.025858 5.145% 114.9
> 225
> kwakeup PreempT 0.017337 3.450% 4334.2
> 4
> read PreempT 0.016161 3.216% 256.5
> 63
> ioctl PreempT 0.013858 2.757% 533.0
> 26
> sigtimedwait PreempT 0.004531 0.902% 453.1
> 10
> gettimeofday PreempT 0.003971 0.790% 152.7
> 26
> lwp_create PreempT 0.003628 0.722% 181.4
> 20
> ksleep PreempT 0.001939 0.386% 121.2
> 16
> close PreempT 0.001631 0.325% 81.6
> 20
> - Skip remainder, SPU of 0.0008 is below '-m 0.0010' Sec

> -------------------------------------------------------------------------------
> Section 1.3: Time Process Blocked
> -------------------------------------------------------------------------------
> TOTAL BlockeD 2.666787 100.000% 844.7
> 3157
> poll BlockeD 2.002994 75.109% 2101.8
> 953
> Preempt PreempT 0.502555 18.845% 318.1
> 1580
> recv BlockeD 0.068728 2.577% 384.0
> 179
> write BlockeD 0.046070 1.728% 202.1
> 228
> ksleep BlockeD 0.034905 1.309% 2181.6
> 16
> ioctl BlockeD 0.014497 0.544% 536.9
> 27
> sigtimedwait BlockeD 0.013226 0.496% 1322.6
> 10
> accept BlockeD 0.004590 0.172% 327.8
> 14
> - Skip remainder, SPU of 0.0010 is below '-m 0.0010' Sec

>


> ================================================== ===========================
> ================================================== ===========================
> The prospect output when the socket is closed after every request is
> as follows.


> encycsrvr7 (07410)NM Birth (pre-exist) ps:=
> (/actu01/ibondre/DEV040120/AcServer/bin/encycs
> rvr7 -Spmd -Q81)
> Process did not END - use last SLEEP

> First execution after benchmark start = 0.003 Seconds

> KI Elapsed Time = 60.003979 100.000% Total
> KTC Elapsed Time = 217.871878 363.096% Total
> KTC Run Time = 27.716669 12.722%
> KTC Not Charged Time = 190.155208 87.278%

> Sorted List of SPUs Used for this Process: [(2:26%), (0:25%), (1:25%),
> (3:24%)]

> -------------------------------------------------------------------------------
> Section 1.0: Sorted Execution+Blocked=Elapsed Clocks for this Process,
> EPB
> -------------------------------------------------------------------------------
> Clock Type Seconds % Elapsed uSec/Count
> Counts

> ELAPSED TOTAL 27.716669 100.000% Total
> EXECUTION TOTAL 25.600633 92.365% Total
> Execution UseR 18.064501 65.176% 38.9
> 464853
> Execution Sys 6.038643 21.787% 16.4
> 367401
> BLOCKED TOTAL 2.116037 7.635% 1284.0
> 1648
> Blocked misc 2.031626 7.330% 2486.7
> 817
> Execution IntUseR 0.993137 3.583% 32.8
> 30318
> Execution IntSys 0.269954 0.974% 22.7
> 11870
> Execution CsW 0.225448 0.813% 3.4
> 66172
> Blocked PreempT 0.084410 0.305% 101.6
> 831
> Execution TraP 0.006501 0.023% 6.9
> 945
> Execution VfaulT 0.002450 0.009% 144.1
> 17

> -------------------------------------------------------------------------------
> Section 1.1: Time Process Executed during System Calls
> -------------------------------------------------------------------------------
> TOTAL Sys 6.038643 100.000% 16.4
> 367401
> write Sys 1.858111 30.770% 10.0
> 186610
> poll Sys 0.863837 14.305% 13.2
> 65285
> read Sys 0.780819 12.930% 15.7
> 49699
> close Sys 0.763243 12.639% 73.8
> 10343
> accept Sys 0.398319 6.596% 77.1
> 5165
> socket Sys 0.396285 6.562% 76.7
> 5167
> connect Sys 0.336425 5.571% 65.1
> 5167
> lwp_create Sys 0.171709 2.843% 33.2
> 5165
> setsockopt Sys 0.127257 2.107% 24.6
> 5165
> lwp_detached_exit Sys 0.106290 1.760% 20.6
> 5170
> recv Sys 0.103426 1.713% 20.0
> 5166
> gettimeofday Sys 0.054678 0.905% 5.2
> 10502
> sched_yield Sys 0.042005 0.696% 17.6
> 2384
> time Sys 0.035094 0.581% 3.2
> 10962
> ksleep Sys 0.010853 0.180% 40.5
> 268
> kwakeup Sys 0.003401 0.056% 32.7
> 104
> sigtimedwait Sys 0.001524 0.025% 20.9
> 73
> clock_gettime Sys 0.001089 0.018% 6.5
> 167
> - Skip remainder, SPU of 0.0005 is below '-m 0.0010' Sec

> -------------------------------------------------------------------------------
> Section 1.2: Time Process Preempted in System Calls
> -------------------------------------------------------------------------------
> TOTAL PreempT 0.084410 100.000% 101.6
> 831
> recv PreempT 0.038530 45.646% 458.7
> 84
> poll PreempT 0.038076 45.108% 62.4
> 610
> read PreempT 0.002635 3.122% 90.9
> 29
> connect PreempT 0.001419 1.681% 67.6
> 21
> write PreempT 0.001276 1.512% 24.5
> 52
> - Skip remainder, SPU of 0.0006 is below '-m 0.0010' Sec

> -------------------------------------------------------------------------------
> Section 1.3: Time Process Blocked
> -------------------------------------------------------------------------------
> TOTAL BlockeD 2.116037 100.000% 1284.0
> 1648
> poll BlockeD 1.744862 82.459% 2917.8
> 598
> recv BlockeD 0.136402 6.446% 1684.0
> 81
> Preempt PreempT 0.084410 3.989% 101.6
> 831
> write BlockeD 0.046357 2.191% 874.7
> 53
> read BlockeD 0.037055 1.751% 1235.2
> 30
> sigtimedwait BlockeD 0.026671 1.260% 13335.6
> 2
> connect BlockeD 0.025623 1.211% 1220.2
> 21
> ksleep BlockeD 0.011171 0.528% 1861.8
> 6
> lwp_create BlockeD 0.001687 0.080% 843.3
> 2
> time BlockeD 0.001244 0.059% 177.7
> 7
> - Skip remainder, SPU of 0.0004 is below '-m 0.0010' Sec

--
portable adj, code that compiles under more than one compiler
these opinions are mine, all mine; HP might not want them anyway...
feel free to post, OR email to raj in cup.hp.com but NOT BOTH...