Назад | Перейти на главную страницу

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

Мы используем Java Hotspot 1.6 с 10.3.6 WebLogic Cluster с 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 и не видим полных сборщиков мусора в журналах сборщика мусора.

Однако мы получаем ошибки тайм-аута у клиентов, пытающихся подключиться к 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?

С уважением.

После долгого расследования мы наконец нашли причину проблемы, пока 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 https://stackoverflow.com/questions/31188663/disables-pkcs11-solaris-implementation

Мы решили отключить реализацию Solaris pkcs11 с помощью «-Dsun.security.pkcs11.enable-solaris = false». Как только мы это сделали, все таймауты исчезли, пропусков в журналах доступа больше не было после GC.

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