Customer runs the option trading application DBStar on top of Sybase Jaguar
application server on E10K. Jaguar 3.01 embeds the JVM from JDK 1.1.8_002
Reference Release. The clients connect mainly via IIOP.

During a trading day, the response times of the clients happen to vary
more and more. While initially and also at most times the response time
is significantly below one second, it happens, that an increasing rate of
requests show degrading performance. According to the customer the response
time could be as bad as 15 seconds.

Here is the customers current production setup and original complaint:

 Sun E10000
 Sybase Jaguar 3.01 EBF
 JDK1.1.8_02 Reference Release
 All required patches for Solaris 2.6

Following is a longer list of the server access time from the client.
The client tries every 500 ms to get new data from the server. The statistics
show the date, the time needed for the request, a counter and the average.
One can easily see that every 3-4 seconds it takes over 5 seconds until the
response is received.
This means that at this moment most time is used for garbage collection.

[16.02.00 17:26:35.263] Kalista Acc. Time: 0 [ms] Acc. Count: 1182 Avg. Time: 828
[16.02.00 17:26:35.810] Kalista Acc. Time: 31 [ms] Acc. Count: 1183 Avg. Time: 827
[16.02.00 17:26:45.232] Kalista Acc. Time: 8797 [ms] Acc. Count: 1184 Avg. Time: 834
[16.02.00 17:26:45.810] Kalista Acc. Time: 31 [ms] Acc. Count: 1185 Avg. Time: 833
[16.02.00 17:26:46.420] Kalista Acc. Time: 0 [ms] Acc. Count: 1186 Avg. Time: 832
[16.02.00 17:26:46.935] Kalista Acc. Time: 0 [ms] Acc. Count: 1187 Avg. Time: 832
[16.02.00 17:26:47.467] Kalista Acc. Time: 32 [ms] Acc. Count: 1188 Avg. Time: 831
[16.02.00 17:26:48.029] Kalista Acc. Time: 16 [ms] Acc. Count: 1189 Avg. Time: 830
[16.02.00 17:26:48.592] Kalista Acc. Time: 32 [ms] Acc. Count: 1190 Avg. Time: 830
[16.02.00 17:26:50.920] Kalista Acc. Time: 1719 [ms] Acc. Count: 1191 Avg. Time: 830
[16.02.00 17:26:54.826] Kalista Acc. Time: 3391 [ms] Acc. Count: 1192 Avg. Time: 832
[16.02.00 17:26:55.342] Kalista Acc. Time: 16 [ms] Acc. Count: 1193 Avg. Time: 832
[16.02.00 17:26:55.842] Kalista Acc. Time: 0 [ms] Acc. Count: 1194 Avg. Time: 831
[16.02.00 17:26:56.373] Kalista Acc. Time: 16 [ms] Acc. Count: 1195 Avg. Time: 830
[16.02.00 17:26:56.873] Kalista Acc. Time: 0 [ms] Acc. Count: 1196 Avg. Time: 830
[16.02.00 17:26:57.389] Kalista Acc. Time: 16 [ms] Acc. Count: 1197 Avg. Time: 829
[16.02.00 17:26:57.904] Kalista Acc. Time: 15 [ms] Acc. Count: 1198 Avg. Time: 828
[16.02.00 17:26:58.467] Kalista Acc. Time: 16 [ms] Acc. Count: 1199 Avg. Time: 828
[16.02.00 17:27:04.639] Kalista Acc. Time: 5578 [ms] Acc. Count: 1200 Avg. Time: 832
[16.02.00 17:27:05.186] Kalista Acc. Time: 31 [ms] Acc. Count: 1201 Avg. Time: 831
[16.02.00 17:27:05.717] Kalista Acc. Time: 0 [ms] Acc. Count: 1202 Avg. Time: 830
[16.02.00 17:27:06.233] Kalista Acc. Time: 0 [ms] Acc. Count: 1203 Avg. Time: 830
[16.02.00 17:27:06.780] Kalista Acc. Time: 47 [ms] Acc. Count: 1204 Avg. Time: 829
[16.02.00 17:27:07.483] Kalista Acc. Time: 47 [ms] Acc. Count: 1205 Avg. Time: 828
[16.02.00 17:27:08.155] Kalista Acc. Time: 16 [ms] Acc. Count: 1206 Avg. Time: 828
[16.02.00 17:27:08.686] Kalista Acc. Time: 31 [ms] Acc. Count: 1207 Avg. Time: 827
[16.02.00 17:27:14.530] Kalista Acc. Time: 5203 [ms] Acc. Count: 1208 Avg. Time: 831
[16.02.00 17:27:15.139] Kalista Acc. Time: 62 [ms] Acc. Count: 1209 Avg. Time: 830
[16.02.00 17:27:15.764] Kalista Acc. Time: 0 [ms] Acc. Count: 1210 Avg. Time: 829
[16.02.00 17:27:16.311] Kalista Acc. Time: 47 [ms] Acc. Count: 1211 Avg. Time: 829
[16.02.00 17:27:16.889] Kalista Acc. Time: 31 [ms] Acc. Count: 1212 Avg. Time: 828
[16.02.00 17:27:17.514] Kalista Acc. Time: 0 [ms] Acc. Count: 1213 Avg. Time: 827
[16.02.00 17:27:23.468] Kalista Acc. Time: 5438 [ms] Acc. Count: 1214 Avg. Time: 831
[16.02.00 17:27:23.968] Kalista Acc. Time: 0 [ms] Acc. Count: 1215 Avg. Time: 830
[16.02.00 17:27:24.483] Kalista Acc. Time: 15 [ms] Acc. Count: 1216 Avg. Time: 830
[16.02.00 17:27:24.983] Kalista Acc. Time: 0 [ms] Acc. Count: 1217 Avg. Time: 829
[16.02.00 17:27:25.499] Kalista Acc. Time: 0 [ms] Acc. Count: 1218 Avg. Time: 828
[16.02.00 17:27:26.030] Kalista Acc. Time: 31 [ms] Acc. Count: 1219 Avg. Time: 828
[16.02.00 17:27:26.702] Kalista Acc. Time: 31 [ms] Acc. Count: 1220 Avg. Time: 827
[16.02.00 17:27:32.671] Kalista Acc. Time: 5328 [ms] Acc. Count: 1221 Avg. Time: 831
[16.02.00 17:27:33.202] Kalista Acc. Time: 15 [ms] Acc. Count: 1222 Avg. Time: 830
[16.02.00 17:27:33.718] Kalista Acc. Time: 0 [ms] Acc. Count: 1223 Avg. Time: 829
[16.02.00 17:27:34.234] Kalista Acc. Time: 16 [ms] Acc. Count: 1224 Avg. Time: 829
[16.02.00 17:27:34.749] Kalista Acc. Time: 0 [ms] Acc. Count: 1225 Avg. Time: 828
[16.02.00 17:27:35.265] Kalista Acc. Time: 0 [ms] Acc. Count: 1226 Avg. Time: 827
[16.02.00 17:27:35.781] Kalista Acc. Time: 0 [ms] Acc. Count: 1227 Avg. Time: 827
[16.02.00 17:27:36.327] Kalista Acc. Time: 31 [ms] Acc. Count: 1228 Avg. Time: 826
[16.02.00 17:27:42.093] Kalista Acc. Time: 5250 [ms] Acc. Count: 1229 Avg. Time: 830
[16.02.00 17:27:42.609] Kalista Acc. Time: 0 [ms] Acc. Count: 1230 Avg. Time: 829
[16.02.00 17:27:43.125] Kalista Acc. Time: 0 [ms] Acc. Count: 1231 Avg. Time: 828
[16.02.00 17:27:43.687] Kalista Acc. Time: 62 [ms] Acc. Count: 1232 Avg. Time: 828
[16.02.00 17:27:44.406] Kalista Acc. Time: 63 [ms] Acc. Count: 1233 Avg. Time: 827
[16.02.00 17:27:45.046] Kalista Acc. Time: 15 [ms] Acc. Count: 1234 Avg. Time: 826
[16.02.00 17:27:45.609] Kalista Acc. Time: 16 [ms] Acc. Count: 1235 Avg. Time: 826
[16.02.00 17:27:46.140] Kalista Acc. Time: 15 [ms] Acc. Count: 1236 Avg. Time: 825
[16.02.00 17:27:52.140] Kalista Acc. Time: 5484 [ms] Acc. Count: 1237 Avg. Time: 829
[16.02.00 17:27:52.687] Kalista Acc. Time: 47 [ms] Acc. Count: 1238 Avg. Time: 828
[16.02.00 17:27:53.390] Kalista Acc. Time: 62 [ms] Acc. Count: 1239 Avg. Time: 828
[16.02.00 17:27:54.047] Kalista Acc. Time: 31 [ms] Acc. Count: 1240 Avg. Time: 827
[16.02.00 17:27:54.578] Kalista Acc. Time: 0 [ms] Acc. Count: 1241 Avg. Time: 826
[16.02.00 17:27:55.109] Kalista Acc. Time: 31 [ms] Acc. Count: 1242 Avg. Time: 826
[16.02.00 17:27:55.687] Kalista Acc. Time: 46 [ms] Acc. Count: 1243 Avg. Time: 825
[16.02.00 17:27:57.859] Kalista Acc. Time: 1547 [ms] Acc. Count: 1244 Avg. Time: 826
[16.02.00 17:28:01.500] Kalista Acc. Time: 3125 [ms] Acc. Count: 1245 Avg. Time: 827
[16.02.00 17:28:02.016] Kalista Acc. Time: 16 [ms] Acc. Count: 1246 Avg. Time: 827
[16.02.00 17:28:02.547] Kalista Acc. Time: 16 [ms] Acc. Count: 1247 Avg. Time: 826
[16.02.00 17:28:03.063] Kalista Acc. Time: 16 [ms] Acc. Count: 1248 Avg. Time: 825
[16.02.00 17:28:03.735] Kalista Acc. Time: 32 [ms] Acc. Count: 1249 Avg. Time: 825
[16.02.00 17:28:04.297] Kalista Acc. Time: 31 [ms] Acc. Count: 1250 Avg. Time: 824
[16.02.00 17:28:04.844] Kalista Acc. Time: 16 [ms] Acc. Count: 1251 Avg. Time: 824
[16.02.00 17:28:10.641] Kalista Acc. Time: 5281 [ms] Acc. Count: 1252 Avg. Time: 827



Looking at a pstack trace from such a process shows, that nearly all threads
are suspended. Only GC is active:

lwp#29 ----------
 eefe2e28 markChildren (d3664cc0, d36477a0, d4f4e178, ef043190, 1, c00) + 334
 eefe5894 gc0_locked (ef046db4, ef043190, ef046c70, ef042e34, 3, ccf472ec) + 66c
 eefe6978 gc (0, ffffffff, ef046c00, ef043000, ef043000, ef043000) + 88
 eefdac8c Java_java_lang_Runtime_gc_stub (7d06920, 7d04f18, 1, ef046d28, ef042400, 34822fa1) + 4
 eefd8414 invokeNativeMethod (7d068f8, 6dd12fc, 7d06920, 7d04f18, eefd7f7c, 7c) + 64
 ef015d50 ExecuteJava (6cc868b, 7d04f18, 7d06920, 7d068f8, 6cc6f20, 7d068f8) + 7d0
 eefed680 jni_Invoke (7d04f18, 6e96066, 6e96364, 6e96220, eda912f0, 0) + 3c0
 eefefca8 jni_CallStaticObjectMethodV (7d04f2c, ffffffe6, 6e96364, eda91460, 80, 0) + 2c
 eeff5254 invoke_CallStaticObjectMethodV (7d04f2c, ffffffe6, 6e96364, eda91460, 7d067b8, 0) + 40
 ef5f2bf4 __0fHJNIEnv_WCallStaticObjectMethodP6H_jclassP6K_jmethodIDe (7d04f2c, ffffffe6, 6e96364, ffffffe5, 4, 6) + 74
 ef5f0770 __0fKJNI_ObjectGinvokeP6K_jagstreamP6J_jagchars (80, 7d006d0, 7d0078c, a0000005, 1f000000, 34) + 848
 ef5ce150 __0fMActualInvokeGinvokeP6OBindThreadWorkT (eda919b4, 1, ef779490, ef776ac0, 7215560, 32) + 488
 ef5d00e8 __0fKCTS_ObjectGinvokeP6K_jagstreamPvP6J_jagcharsP6K_jagoctetsScT (7d006d0, 2cad78, 7d0078c, 7d00784, 1, ff00) + ef0
 ef5e0e18 IIOP_localHandler (7d006d0, 6e683d8, ef776ac0, ef70e218, 0, 7d006d0) + a8
 ef658050 __0FKrunServicePv (6e683d8, 2cad78, 4356, ef776ac0, 3000, 3108) + 1f8
 ef452860 srv__spawnfunc (2cad78, ef475ae8, ef48a014, 3000, ef475ae8, 6c918) + 34
 ef220610 background_thread (74b50, ef243250, ef243254, ef241bd0, ef45bf88, 2cad78) + c8
 ef7557b4 tml__thread_start (74418, ef776ac0, 0, ef0d0a04, 1, fe401000) + a4
 ef0b641c _thread_start (74418, 0, 0, 0, 0, 0) + 40

Please find a complete pstack trace attached. The pstack was drawn on
March 9, 2000 after trading hours.


At least lwp#57 seems not to be blocked on a condition variable:

lwp#57 ----------
 eecb9e74 recv (46, d44c8bb4, 5ab, 0)
 eecb9e74 _so_recv (46, d44c8bb4, 5ab, 0, 10, edea1e2c) + 8
 ef014c00 sysRecvFD (d440ccc0, d44c8bb4, 5ab, 0, 7d17138, 7d16c3c) + 64
 ed06538c java_net_SocketInputStream_socketRead (d35c5de0, ed077624, 28c, 5ab, d44c8928, d440ccc0) + 1fc
 ed066b34 Java_java_net_SocketInputStream_socketRead_stub (7d171f0, 7d171ec, 1, ef046d28, 6e000000, 34e3c1b8) + 18
 eefd8414 invokeNativeMethod (7d171c4, 6ef9ae4, 7d171ec, 7d11848, eefd7f7c, 6ef96d8) + 64
 ef015d50 ExecuteJava (6ef9e3d, 7d11848, 7d171ec, 7d171b0, 6ef96d8, 7d171c4) + 7d0
 eefed680 jni_Invoke (7d11848, 6ebb166, 10, 6ebb5b8, edea0778, 7d16d88) + 3c0
 eefefca8 jni_CallStaticObjectMethodV (7d1185c, ffffffdc, 6ebb7a4, edea08e8, a5, 19) + 2c
 eeff5254 invoke_CallStaticObjectMethodV (7d1185c, ffffffdc, 6ebb7a4, edea08e8, 7d12600, edea13a0) + 40
 ef5f2bf4 __0fHJNIEnv_WCallStaticObjectMethodP6H_jclassP6K_jmethodIDe (7d1185c, ffffffdc, 6ebb7a4, ffffffdb, b, d) + 74
 ef5f0770 __0fKJNI_ObjectGinvokeP6K_jagstreamP6J_jagchars (8c, 7fe4790, 7fe484c, a0000005, 1f000000, 34) + 848
 ef5ce150 __0fMActualInvokeGinvokeP6OBindThreadWorkT (edea0e3c, 1, ef779490, ef776ac0, 746f250, 32) + 488
 ef5d00e8 __0fKCTS_ObjectGinvokeP6K_jagstreamPvP6J_jagcharsP6K_jagoctetsScT (7fe4790, 2cc628, 7fe484c, 7fe4844, 0, 7d12600) + ef0
 ef5ed8cc __0FTJNI_LocalSocketCallP6HJNIEnv_P6I_jobjectP6L_jbyteArrayl (7d1185c, 8, 9, a5, 6, 1) + 1cc
 ef01547c sysInvokeNative (7d1185c, ef5ed700, 7d16db4, 6d96358, 0, 0) + b8
 eefd8728 invokeJNINativeMethod (7d16dc0, 6d96634, 0, 7d11848, 7, 7d1185c) + 1e0
 ef015d50 ExecuteJava (6dc509a, 7d11848, 7d16db4, 7d16d78, 6dc4d10, 7d16d88) + 7d0
 eefed680 jni_Invoke (7d11848, 71da686, 71da9e4, 71da850, edea12f0, 0) + 3c0
 eefefca8 jni_CallStaticObjectMethodV (7d1185c, ffffffbb, 71da9e4, edea1460, 80, 0) + 2c
 eeff5254 invoke_CallStaticObjectMethodV (7d1185c, ffffffbb, 71da9e4, edea1460, 7d12600, 0) + 40
 ef5f2bf4 __0fHJNIEnv_WCallStaticObjectMethodP6H_jclassP6K_jmethodIDe (7d1185c, ffffffbb, 71da9e4, ffffffb9, 4, 6) + 74
 ef5f0770 __0fKJNI_ObjectGinvokeP6K_jagstreamP6J_jagchars (80, 7d04f80, 7d0503c, a0000005, 1f000000, 34) + 848
 ef5ce150 __0fMActualInvokeGinvokeP6OBindThreadWorkT (edea19b4, 1, ef779490, ef776ac0, 7038c18, 32) + 488
 ef5d00e8 __0fKCTS_ObjectGinvokeP6K_jagstreamPvP6J_jagcharsP6K_jagoctetsScT (7d04f80, 2cc628, 7d0503c, 7d05034, 1, ff00) + ef0
 ef5e0e18 IIOP_localHandler (7d04f80, 7035250, ef776ac0, ef70e218, 0, 7d04f80) + a8
 ef658050 __0FKrunServicePv (7035250, 2cc628, 4356, ef776ac0, 3000, 3108) + 1f8
 ef452860 srv__spawnfunc (2cc628, ef475ae8, ef48a014, 3000, ef475ae8, 6c918) + 34
 ef220610 background_thread (7ced950, ef243250, ef243254, ef241bd0, ef45bf88, 2cc628) + c8
 ef7557b4 tml__thread_start (73b28, ef776ac0, 0, ef0d0a04, 1, fe401000) + a4
 ef0b641c _thread_start (73b28, 0, 0, 0, 0, 0) + 40

Furthermore lwp#58, lwp#65 and lwp#73 are in "poll".