Сервер WebLogic зависает после запуска CMS Garbage Collection

Мы используем Java Hotspot 1.6 с версией 10.3.6 Кластер WebLogic с 2 узлами под управлением OSB 11.1.1.7 за балансировщиком физической нагрузки:

java version "1.6.0_91"
Java(TM) SE Runtime Environment (build 1.6.0_91-b13)
Java HotSpot(TM) 64-Bit Server VM (build 20.91-b07, mixed mode)

Мы настроили JVM для использования CMS и избежания длительной сборки мусора:

-XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:NewRatio=4 -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=60 -XX:+ScavengeBeforeFullGC -XX:+CMSScavengeBeforeRemark

Большинство фаз паузы сборщиков мусора (начальная отметка и замечание) занимает менее секунды, мы не видим сбоев при запуске CMS и не видим полных сборщиков мусора в журналах gc.

Однако мы получаем ошибки тайм-аута на клиентах, пытающихся подключиться к OSB через несколько секунд после завершения выполнения CMS GC (особенно в установке Oracle SOA с большим количеством композитов, вызывающих OSB):

OSB 1 gc. log:

> 2016-07-28T08:31:52.656-0300: 492247.689: [GC
> 2016-07-28T08:31:52.656-0300: 492247.690: [ParNew:
> 1027265K->22014K(1132416K), 0.0412613 secs]
> 4046262K->3043322K(6165632K), 0.0420791 secs] [Times: user=0.25
> sys=0.00, real=0.04 secs]  2016-07-28T08:31:52.701-0300: 492247.735:
> [GC [1 CMS-initial-mark: 3021307K(5033216K)] 3043844K(6165632K),
> 0.0683781 secs] [Times: user=0.08 sys=0.00, real=0.07 secs]  2016-07-28T08:31:52.770-0300: 492247.804: [CMS-concurrent-mark-start]
> 2016-07-28T08:31:56.971-0300: 492252.005: [CMS-concurrent-mark:
> 4.201/4.201 secs] [Times: user=10.55 sys=0.16, real=4.20 secs]  2016-07-28T08:31:56.971-0300: 492252.005:
> [CMS-concurrent-preclean-start] 2016-07-28T08:31:57.064-0300:
> 492252.098: [CMS-concurrent-preclean: 0.090/0.093 secs] [Times: user=0.12 sys=0.00, real=0.09 secs]  2016-07-28T08:31:57.064-0300:
> 492252.098: [CMS-concurrent-abortable-preclean-start] 2016-07-28T08:32:01.198-0300: 492256.231: [GC
> 2016-07-28T08:32:01.198-0300: 492256.232: [ParNew:
> 1028128K->30711K(1132416K), 0.0502326 secs]
> 4049435K->3053383K(6165632K), 0.0508313 secs] [Times: user=0.34
> sys=0.00, real=0.05 secs] CMS: abort preclean due to time
> 2016-07-28T08:32:02.128-0300: 492257.161:
> [CMS-concurrent-abortable-preclean: 4.027/5.063 secs] [Times:
> user=7.62 sys=0.24, real=5.06 secs]  2016-07-28T08:32:02.134-0300:
> 492257.167: [GC[YG occupancy: 186361 K (1132416 K)]2016-07-28T08:32:02.134-0300: 492257.167: [GC
> 2016-07-28T08:32:02.134-0300: 492257.167: [ParNew:
> 186361K->25052K(1132416K), 0.0231613 secs]
> 3209034K->3049538K(6165632K), 0.0236069 secs] [Times: user=0.17
> sys=0.00, real=0.02 secs]  2016-07-28T08:32:02.158-0300: 492257.191:
> [Rescan (parallel) , 0.0289939 secs]2016-07-28T08:32:02.187-0300:
> 492257.220: [weak refs processing, 0.3412320 secs] [1 CMS-remark: 3024485K(5033216K)] 3049538K(6165632K), 0.4179878 secs] [Times:
> user=0.67 sys=0.00, real=0.42 secs]  2016-07-28T08:32:02.552-0300:
> 492257.586: [CMS-concurrent-sweep-start] 2016-07-28T08:32:07.144-0300: 492262.177: [CMS-concurrent-sweep: 4.591/4.591 secs] [Times: user=14.05 sys=0.22, real=4.59 secs]  2016-07-28T08:32:07.146-0300:
> 492262.180: [CMS-concurrent-reset-start] 2016-07-28T08:32:07.283-0300: 492262.316: [CMS-concurrent-reset: 0.137/0.137 secs] [Times: user=0.36 sys=0.01, real=0.14 secs]  2016-07-28T08:32:36.201-0300: 492291.234:
> [GC 2016-07-28T08:32:36.202-0300: 492291.234: [ParNew:
> 1030955K->45449K(1132416K), 0.0671313 secs]
> 2269248K->1285059K(6165632K), 0.0676485 secs] [Times: user=0.41
> sys=0.00, real=0.07 secs]

Есть в журнале доступа OSB WebLogic, что мы заметили это странное поведение, обычно через 5 или 10 секунд после запуска CMS, между запросами в журнале доступа есть 20+ секундный промежуток, когда обычно мы видим десятки вызовов в секунду .

Журнал доступа к OSB1:

2016-07-28 08:32:03 POST /service1/ 200 0.043  
2016-07-28 08:32:03 POST /service1/ 200 0.074   
2016-07-28 08:32:03 POST /service1/ 200 0.045   
2016-07-28 08:32:03 POST /service1/ 200 0.053   
2016-07-28 08:32:35 POST /service1/ 200 0.076

И в то же время некоторые вызовы, сделанные с сервера SOA, терпят неудачу:

Ошибка журнала SOA: https://esburl.mycompany.com/service1 " успешно из-за: Не удалось вызвать URI конечной точки « https://esburl.mycompany.com/service1 » успешно из-за: javax.xml.soap.SOAPException: javax.xml.soap.SOAPException: сообщение отправлено не удалось: истекло время чтения>

В журнале вывода OSB weblogic не сообщается об ошибках. Мы сделали несколько потоковых дампов во время работы GC, но не смогли точно определить проблему. Мы подумали, что если первоначальная отметка и замечание были достаточно быстро, мы бы не увидели таких проблем, но у нас все еще есть сомнения относительно того, является ли это JVM, WebLogic или проблема приложения (OSB).Кто-нибудь видел что-то подобное с WebLogic или другим сервером приложений?

Спасибо!

РЕДАКТИРОВАТЬ:

Похоже, проблема связана с SSL:

~$ curl -v -k https://mycompany.com:9001/service1/ -o /dev/null 
* Hostname was NOT found in DNS cache
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying x.x.x.x...
* Connected to mycompany.com (x.x.x.x) port 9001 (#0)
* successfully set certificate verify locations:
*   CAfile: none
  CApath: /etc/ssl/certs
* SSLv3, TLS handshake, **Client hello** (1):
} [data not shown]
  0     0    0     0    0     0      0      0 --:--:--  **0:00:16** --:--:--     0* 
  SSLv3, TLS handshake, **Server hello** (2):
{ [data not shown]
* SSLv3, TLS handshake, CERT (11):
{ [data not shown]
* SSLv3, TLS handshake, Server key exchange (12):
{ [data not shown]
* SSLv3, TLS handshake, Server finished (14):
{ [data not shown]
* SSLv3, TLS handshake, Client key exchange (16):
} [data not shown]
* SSLv3, TLS change cipher, Client hello (1):
} [data not shown]
* SSLv3, TLS handshake, Finished (20):
} [data not shown]
* SSLv3, TLS change cipher, Client hello (1):
{ [data not shown]
* SSLv3, TLS handshake, Finished (20):
{ [data not shown]
* SSL connection using EDH-RSA-DES-CBC3-SHA
* Server certificate:
*    subject: C=xx; ST=xx; L=xx; O=xx; OU=Tech; CN=mycompany.com
*    start date: 2016-02-25 13:17:10 GMT
*    expire date: 2021-02-23 13:17:10 GMT
*    issuer: DC=xx; DC=xx; DC=xx; CN=xx
*    SSL certificate verify result: self signed certificate in certificate chain (19), continuing anyway.
> GET /service1 HTTP/1.1
> User-Agent: curl/7.35.0
> Host: mycompany.com:9001
> Accept: */*
> 
< HTTP/1.1 200 OK
< Date: Wed, 03 Aug 2016 15:46:41 GMT
< Transfer-Encoding: chunked
< Content-Type: text/xml; charset=UTF-8
< X-Powered-By: Servlet/2.5 JSP/2.1

Кажется, что при выполнении GC серверу требуется много времени для завершения подтверждения SSL (в этом примере 16 секунд) Но я не Понятия не имею, почему. Кто-нибудь знает о каких-либо проблемах Java, связанных с GC и протоколом SSL?

С уважением.

0
задан 3 August 2016 в 20:31
1 ответ

После долгого исследования мы, наконец, нашли причину проблемы. Во время работы CMS GC мы сделали несколько дампов потоков и обнаружили этот заметный стек в 5 или 6 потоках:

"[ACTIVE] ExecuteThread: '35' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=3 tid=0x000000001333c000 nid=0xa1 runnable [0xfffffd7e23dd1000] 
   java.lang.Thread.State: RUNNABLE 
at sun.security.pkcs11.wrapper.PKCS11.C_DestroyObject(Native Method) 
at sun.security.pkcs11.SessionKeyRef.dispose(P11Key.java:1043) 
at sun.security.pkcs11.SessionKeyRef.drainRefQueueBounded(P11Key.java:1019) 
at sun.security.pkcs11.SessionKeyRef. (P11Key.java:1034) 
at sun.security.pkcs11.P11Key. (P11Key.java:98) 
at sun.security.pkcs11.P11Key$P11SecretKey. (P11Key.java:379) 
at sun.security.pkcs11.P11Key.secretKey(P11Key.java:271) 
at sun.security.pkcs11.P11TlsRsaPremasterSecretGenerator.engineGenerateKey(P11TlsRsaPremasterSecretGenerator.java:84) 
at javax.crypto.KeyGenerator.generateKey(DashoA13*..) 
at com.sun.net.ssl.internal.ssl.RSAClientKeyExchange. (RSAClientKeyExchange.java:68) 
at com.sun.net.ssl.internal.ssl.ClientHandshaker.serverHelloDone(ClientHandshaker.java:807) 
at com.sun.net.ssl.internal.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:286) 
at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:608) 
at com.sun.net.ssl.internal.ssl.Handshaker$1.run(Handshaker.java:548) 
at java.security.AccessController.doPrivileged(Native Method) 
at com.sun.net.ssl.internal.ssl.Handshaker$DelegatedTask.run(Handshaker.java:941) 
- locked <0xfffffd7e402b5ca0> (a com.sun.net.ssl.internal.ssl.SSLEngineImpl)

выполнение этого кода присутствовало в том же потоке в дампах, разделенных на 20-25 секунд, так что это казалось очень хорошим подозрением.

После просмотра документации Oracle Supports и этих ссылок:

https: //bugs.openjdk. java.net/browse/JDK-8059337 enable-solaris = false ". Как только мы это сделали, все таймауты исчезли, пропусков в журналах доступа больше не было после GC.

Я не уверен, есть ли какое-либо преимущество использования sun pcks11 перед другими провайдерами, но его отключение, похоже, решает нашу проблему, и пока не обнаружено новой проблемы, вызванной этим изменением, поэтому мы собираемся придерживаться с ним.

2
ответ дан 4 December 2019 в 13:39

Теги

Похожие вопросы