пятница, 9 июня 2017 г.

Валидация DVM после обновления потребляет весь CPU, или как мы заставили Oracle выпустить patch

Постановка задачи


Пришли как-то к Суровому коллеги с интересным вопросом. Суть в следующем: каждый раз после обновления MDS производительность промышленного контура одной немаленькой системы, написанной на Oracle SOA Suite, критически падает, при этом загрузка центральных процессоров серверов, на которых развернута система, очень сильно возрастает.

Особенностью системы является активное использование такого механизма Oracle SOA Suite как Domain Value Maps (DVM), предназначенного для перекодировки значений из ограниченного набора одной предметной области (при интеграции - одной информационной системы) в значения, характерные для другой предметной области (информационной системы). Например наши любимые российские рубли в одной системе могут кодироваться как RUR, а в другой - 810. Механизм DVM удобен для работы со справочниками конвертации, которые изменяются нечасто, однако, если все же справочник требуется изменить, то в состав Oracle SOA Suite входит инструмент с развитым веб-интерфейсом - SOA Composer, - позволяющий сделать это бизнес-пользователю без привлечения разработчиков.

Как оказалось, все работает идеально пока такие справочники небольшие, однако если их размер увеличивается до сотен килобайт, то пользователей и администраторов Oracle SOA Suite ждут сюрпризы.

Посмотрим на дамп потоков, собранный во время, когда наблюдалась проблема.

"[ACTIVE] ExecuteThread: '57' for queue: 'weblogic.kernel.Default (self-tuning)'" #159 daemon prio=9 os_prio=2 tid=0x0000000066bbd800 nid=0x28ac runnable [0x0000000079188000]
java.lang.Thread.State: RUNNABLE
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:600)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.xpath.ComparisonExpr.evaluate(XSLExpr.java:1743)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XPathPredicate.filter(XPathPredicate.java:349)
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:627)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2762)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2722)
at oracle.tip.dvm.sdk.util.XMLUtil.isDVMDocumentValid(XMLUtil.java:211)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:202)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:130)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:217)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:133)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:252)
at sun.reflect.GeneratedMethodAccessor1815.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at oracle.xml.xpath.XSLExtFunctions.callStaticMethod(XSLExtFunctions.java:115)
at oracle.xml.xpath.XPathExtFunction.evaluateMethod(XPathExtFunction.java:422)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:347)
at oracle.xml.xslt.XSLValueOf.processAction(XSLValueOf.java:152)
at oracle.xml.xslt.XSLNode.processChildren(XSLNode.java:559)
at oracle.xml.xslt.XSLTemplate.processAction(XSLTemplate.java:278)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:706)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:665)
at oracle.xml.xslt.XSLProcessor.processXSL(XSLProcessor.java:401)
at oracle.xml.jaxp.JXTransformer.transform(JXTransformer.java:578)
at ...


"[ACTIVE] ExecuteThread: '56' for queue: 'weblogic.kernel.Default (self-tuning)'" #158 daemon prio=9 os_prio=2 tid=0x0000000066bbc800 nid=0x4f4 runnable [0x0000000078f78000]
java.lang.Thread.State: RUNNABLE
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:600)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.xpath.ComparisonExpr.evaluate(XSLExpr.java:1743)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XPathPredicate.filter(XPathPredicate.java:349)
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:627)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2762)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2722)
at oracle.tip.dvm.sdk.util.XMLUtil.isDVMDocumentValid(XMLUtil.java:211)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:202)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:130)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:217)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:133)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:252)
at sun.reflect.GeneratedMethodAccessor1815.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at oracle.xml.xpath.XSLExtFunctions.callStaticMethod(XSLExtFunctions.java:115)
at oracle.xml.xpath.XPathExtFunction.evaluateMethod(XPathExtFunction.java:422)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:347)
at oracle.xml.xslt.XSLValueOf.processAction(XSLValueOf.java:152)
at oracle.xml.xslt.XSLNode.processChildren(XSLNode.java:559)
at oracle.xml.xslt.XSLTemplate.processAction(XSLTemplate.java:278)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:706)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:665)
at oracle.xml.xslt.XSLProcessor.processXSL(XSLProcessor.java:401)
at oracle.xml.jaxp.JXTransformer.transform(JXTransformer.java:578)
at ...

"[ACTIVE] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)'" #104 daemon prio=9 os_prio=2 tid=0x000000005edf3800 nid=0x2e30 runnable [0x000000006e059000]
java.lang.Thread.State: RUNNABLE
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XPathPredicate.filter(XPathPredicate.java:349)
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:627)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2762)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2722)
at oracle.tip.dvm.sdk.util.XMLUtil.isDVMDocumentValid(XMLUtil.java:211)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:202)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:130)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:217)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:133)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:252)
at sun.reflect.GeneratedMethodAccessor1815.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at oracle.xml.xpath.XSLExtFunctions.callStaticMethod(XSLExtFunctions.java:115)
at oracle.xml.xpath.XPathExtFunction.evaluateMethod(XPathExtFunction.java:422)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:347)
at oracle.xml.xslt.XSLValueOf.processAction(XSLValueOf.java:152)
at oracle.xml.xslt.XSLNode.processChildren(XSLNode.java:559)
at oracle.xml.xslt.XSLTemplate.processAction(XSLTemplate.java:278)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:706)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:665)
at oracle.xml.xslt.XSLProcessor.processXSL(XSLProcessor.java:401)
at oracle.xml.jaxp.JXTransformer.transform(JXTransformer.java:578)
at ...

"[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'" #25 daemon prio=9 os_prio=2 tid=0x000000005bbaa000 nid=0x2acc runnable [0x0000000062268000]
java.lang.Thread.State: RUNNABLE
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:600)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.xpath.ComparisonExpr.evaluate(XSLExpr.java:1743)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:514)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:524)
at oracle.xml.xpath.XPathPredicate.filter(XPathPredicate.java:349)
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:627)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:1102)
at oracle.xml.xpath.PathExpr.evaluate(PathExpr.java:808)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2762)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2722)
at oracle.tip.dvm.sdk.util.XMLUtil.isDVMDocumentValid(XMLUtil.java:211)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:202)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:130)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:217)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:133)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:252)
at sun.reflect.GeneratedMethodAccessor1815.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at oracle.xml.xpath.XSLExtFunctions.callStaticMethod(XSLExtFunctions.java:115)
at oracle.xml.xpath.XPathExtFunction.evaluateMethod(XPathExtFunction.java:422)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:347)
at oracle.xml.xslt.XSLValueOf.processAction(XSLValueOf.java:152)
at oracle.xml.xslt.XSLNode.processChildren(XSLNode.java:559)
at oracle.xml.xslt.XSLTemplate.processAction(XSLTemplate.java:278)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:706)
at oracle.xml.xslt.XSLStylesheet.execute(XSLStylesheet.java:665)
at oracle.xml.xslt.XSLProcessor.processXSL(XSLProcessor.java:401)
at oracle.xml.jaxp.JXTransformer.transform(JXTransformer.java:578)
at ...


Т.е. потоки заняты работой с XML и осуществляют валидацию DVM. При этом, если дать потокам доработать, то будет видно, что при повторных запросах DVM не валидируется, она будет делать это только после перезапуска сервера или обновления MDS.

Анализ


Был разработан небольшой тестовый композит, содержащий синхронный BPEL-процесс, в котором осуществляется вызов функции dvm:lookupValue, работающей над большим (около 500 кб) DVM-файлом.


В композите используется только одна DVM.


Для проверки гипотезы о влиянии числа потоков валидации DVM на производительность сервера был разработан небольшой бенчмарк с использованием JMH, который лишь отправляет закодированный SOAP-запрос с помощью HTTPUtils на сервер и ждет ответа.

Результаты запуска бенчмарка в режиме Single Shot приведены ниже:

В 1 поток
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       35258,785          ms/op

В 2 потока
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       44261,669          ms/op

В 4 потока
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       58845,936          ms/op

Перед каждым запуском бенчмарка композит обновлялся на сервере.

Очень похоже на ошибку в коде Oracle SOA Suite: даже один и тот же файл DVM валидируется одновременно несколькими потоками, что приводит к большой загрузке процессора и деградации производительности всей системы.

Решение


Был открыт сервисный запрос в службу техподдержки Oracle, которая на удивление оперативно выпустила патч под нашу версию продукта. Патч доступен на mysupport.oracle.com по ссылке:

Patch 26177605 - 11.1.1.7.8 - Large DVMs cause high CPU and stuck threads after startup or redeploy

После установки патча, эксперимент был повторен:

Interim patches (2) :

Patch  26177605     : applied on Wed Jun 07 16:53:02 MSK 2017
Unique Patch ID:  21330144
   Created on 6 Jun 2017, 11:08:12 hrs PST8PDT
   Bugs fixed:
     26177605
   This patch overlays patches:
     20900797
   This patch needs patches:
     20900797
   as prerequisites


В 1 поток:
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       30889.307          ms/op

В 2 потока:
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       35392.957          ms/op

В 4 потока
Benchmark                    (port)   (server)  Mode  Cnt      Score   Error  Units
DVMisValidBenchmark.message    8001  localhost    ss       31056.566          ms/op

В принципе, числа говорят сами за себя, но давайте посмотрим, что делают потоки.


"[ACTIVE] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007f1db0095800 nid=0x7673 waiting for monitor entry [0x00007f1d4b7af000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:198)
- waiting to lock <0x00000007eafc5828> (a oracle.fabric.common.dvm.DVM)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:128)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:274)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:175)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.DVMExtFunctions$LookupValue.call(DVMExtFunctions.java:80)
at oracle.fabric.common.xml.xpath.FabricXPathFunctionWrapper.evaluate(FabricXPathFunctionWrapper.java:84)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.;ava:157)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:126)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:264)
at oracle.xml.xpath.JXPathExpression.evaluate(JXPathExpression.java:203)
at ...

"[ACTIVE] ExecuteThread: '13' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007f1da0008800 nid=0x5fc5 waiting for monitor entry [0x00007f1d55834000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:198)
- waiting to lock <0x00000007eafc5828> (a oracle.fabric.common.dvm.DVM)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:128)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:274)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:175)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.DVMExtFunctions$LookupValue.call(DVMExtFunctions.java:80)
at oracle.fabric.common.xml.xpath.FabricXPathFunctionWrapper.evaluate(FabricXPathFunctionWrapper.java:84)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:157)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:126)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:264)
at oracle.xml.xpath.JXPathExpression.evaluatge(JXPathExpression.java:203)
at ...

"[ACTIVE] ExecuteThread: '8' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007f1db000f800 nid=0x5193 waiting for monitor entry [0x00007f1d55d39000]
java.lang.Thread.State: BLOCKED (on object monitor)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:198)
- waiting to lock <0x00000007eafc5828> (a oracle.fabric.common.dvm.DVM)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:128)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:274)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:175)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.DVMExtFunctions$LookupValue.call(DVMExtFunctions.java:80)
at oracle.fabric.common.xml.xpath.FabricXPathFunctionWrapper.evaluate(FabricXPathFunctionWrapper.java:84)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:157)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:126)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:264)
at oracle.xml.xpath.JXPathExpression.evaluate(JXPathExpression.java:203)


"[ACTIVE] ExecuteThread: '14' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007f1d74011000 nid=0x5fc6 runnable [0x00007f1d5512d000]
java.lang.Thread.State: RUNNABLE
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:607)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:564)
at oracle.xml.xpath.PathExpr.evaluate(XSLNodeSetExpr.java:873)
at oracle.xml.xpath.ComparisonExpr.evaluate(XSLExpr.java:1497)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:420)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:473)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:420)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:473)
at oracle.xml.xpath.XSLExprBase.testBooleanExpr(XSLExprBase.java:420)
at oracle.xml.xpath.AndExpr.evaluate(XSLExpr.java:473)
at oracle.xml.xpath.XPathPredicate.filter(XPathPredicate.java:264)
at oracle.xml.xpath.XPathChildAxis.getNodeList(XPathAxis.java:627)
at oracle.xml.xpath.XPathStep.evaluate(XPathStep.java:564)
at oracle.xml.xpath.PathExpr.evaluate(XSLNodeSetExpr.java:873)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2562)
at oracle.xml.parser.v2.XMLNode.selectNodes(XMLNode.java:2522)
at oracle.tip.dvm.sdk.util.XMLUtil.isDVMDocumentValid(XMLUtil.java:197)
at oracle.tip.dvm.entity.DVMRTObject.validateDVM(DVMRTObject.java:200)
- locked <0x00000007eafc5828> (a oracle.fabric.common.dvm.DVM)
at oracle.tip.dvm.entity.DVMRTObject.(DVMRTObject.java:128)
at oracle.tip.dvm.DVMManagerImpl.getDVMRTObject(DVMManagerImpl.java:274)
at oracle.tip.dvm.DVMManagerImpl.lookupValue(DVMManagerImpl.java:175)
at oracle.tip.dvm.LookupValue.lookupValue(LookupValue.java:95)
at oracle.tip.dvm.DVMExtFunctions$LookupValue.call(DVMExtFunctions.java:80)
at oracle.fabric.common.xml.xpath.FabricXPathFunctionWrapper.evaluate(FabricXPathFunctionWrapper.java:84)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:157)
at oracle.xml.xpath.JXPathContext$JXFunction.invoke(JXPathContext.java:126)
at oracle.xml.xpath.XPathExtFunction.evaluate(XPathExtFunction.java:264)
at oracle.xml.xpath.JXPathExpression.evaluate(JXPathExpression.java:203)
at ...


Знаете, после данного случая, я поверил в известные рассказы IBM о том, что производительность процессоров Intel деградирует с ростом нагрузки на ядро. На данном стенде множество свободных ядер, один поток, осуществляющий валидацию DVM никак не мешает другим потокам, занимающимся этим же, однако при росте числа потоков, выполняющих тяжелую работу над XML-данными производительность системы ощутимо падает. Интересно было бы проверить влияние нагрузки на производительность других процессоров: p Systems или мейнфреймов.

Понравилось сообщение - подпишитесь на блог

6 комментариев:

Yury Schkatula комментирует...

Ну как же "не мешает другим потокам, занимающимся этим же"?

Судя по выжимке из лога, имеем 4 потока, позвавших validateDVM(), из которых 3 ждут на мониторе. Т.е. валидатор явно однопоточный. Включая режим телепатии, могу предположить, что был кусок старого statefull легаси-кода, который затем надо было заставить работать в многопоточном окружении, и в качестве простейшего решения был добавлен блокирующий примитив (вместо того чтобы вынести весь state как входной параметр-контекст и превратить валидатор по сути в статический метод).

Pavel Samolysov комментирует...

Вы говорите о втором дампе потоков, а я в тексте - о первом. Т.е. о том, что вообще странно, что проявляется такая проблема: работают N потоков, где N < меньше числа ядер, исполняют код, в котором нет блокировок и вообще взаимосвязей. Этот код исполняется за X секунд. Если один поток заблокировать, дать ему отвалидировать DVM, а потом остальным - увидеть этот флажок, то время исполнения кода начинает занимать в разы меньше времени. Я понимаю, общие кеши там, общение с памятью, но не настолько же!

Ваше предположение ложное, речь идет о ядре Oracle SOA Suite, причем здесь легаси и уж тем более стейтфул-решения, я не понял.

В любом случае, спасибо Вам за комментарий!

Yury Schkatula комментирует...

Ах, вон оно что - действительно, первый дамп иной. Но после их сравнения я только укоренился в "телепатической гипотезе" :)
Общие кэши, общение с памятью - именно настолько могут оказывать взаимное влияние. Судя по тому, что используется XPath, валидация идёт на DOM-парсере XML, а это очень прожорливое существо даже в однопоточном режиме (парсинг файла даже в 1 мегабайт занимает несколько секунд, дальше - хуже). Плюс древообразный ссылочный характер данных, который активно вымывает кэш-линии, поэтому при одновременной работе нескольких парсеров имеем ситуацию "работа без кэша". Плюс потенциальный false sharing, который на многоядерном окружении тоже серьёзно тормозит исполнение (т.к. блокировки доступа идут аппаратно на уровне шины памяти, а не в коде). Вот и получаем все симптомы из начала статьи.

Pavel Samolysov комментирует...

Синхронизацию скорее всего просто про...ли, по-другому не скажешь.

Была информация от коллег, что на JRockit не воспроизводится, однако чуда не произошло - та же проблема. Просто кластер больше, соответственно запросов (потоков) на один процессор меньше.

Vladimir Zhilyaev комментирует...

Добрый день, Павел, спасибо за статью!
Есть смежный вопрос по SOA Suite 11/12 и обновлению MDS. При определенных изменениях wsdl и xsd в EM при "Test Web Services" не видно изменений, они появляются только после ребута, это неудобно для продакшн систем. Поднимал пост на комьюнити, ни одно из предложенных решений не помогло. https://community.oracle.com/message/13850773

Pavel Samolysov комментирует...

Владимир, добрый день.

Вам пробовали подсказать в направлении как правильно деплоить MDS на SOA Suite. У меня тоже есть инструкция на этот счет: http://samolisov.blogspot.ru/2011/11/oracle-mds.html

Если не помогает - дайте знать, тоже стало интересно, что это за проблема такая с обновлением MDS, не помню даже встречался ли с такой.

Отправить комментарий

Любой Ваш комментарий важен для меня, однако, помните, что действует предмодерация. Давайте уважать друг друга!