View Single Post

   
  #6 (permalink)  
Old 01-16-2008, 05:39 PM
Irfan Bondre
 
Posts: n/a
Default Re: High kernel time while reusing the same socket?

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
Reply With Quote