Mediator Parallel Routing Rules

Introduction

In 11g, mediator executes routing rules either sequentially or in parallel.  If you are planning to use parallel routing rules, you would need to understand how the mediator queues and evaluates routings in parallel in different threads. This article describes 2 different threads used in the parallel routing rules and the design consideration if you are planning to use parallel routing rules in your implementation.

mediator-parallel-routing-rules-1

Main Article

By using parallel routing rules, services can be designed to be truly asynchronous. However, the service engine executes these requests in a rather unique fashion. Let’s say that the average time taken to complete execution of each service is one second. If you were to receive 10 requests on the first Mediator service and the Mediator Service Engine is configured with 10 threads, the expectation is that all requests would be completed within one second. However, that is not the case. Let me elaborate further.

Let’s say you have 3 mediator services deployed to your SOA server and each of these has a single parallel routing rule. When the mediator service received a message, the message would be inserted in Mediator store by the dispatcher, its message metadata would be written to the MEDIATOR_DEFERRED_MESSAGE table, and the payload goes into MEDIATOR_PAYLOAD table. All these would occur on the original calling thread.

The mediator service engine has one thread called Locker thread. The locker thread would surface the message metadata from the MEDIATOR_DEFERRED_MESSAGE table into an internal memory queue. The locker thread does this in its own transaction. The MEDIATOR_DEFERRED_MESSAGE table also has a state listed below:
0 – READY
1 – LOCKED
2 – COMPLETED SUCCESSFULLY
3 – FAULTED

Hence, it is important to understand how the locker thread works behind the scene, as this would affect your design decision:

The locker thread has an algorithm to process the message stored by the dispatcher, and there is only 1 locker thread per managed server. After the dispatcher has stored the message data in the MEDIATOR_DEFERRED_MESSAGE table, the locker thread will lock message(s) that has a state=“0”, the number of message to be locked by the locker thread will be dependent on the Parallel Maximum Rows Retrieved parameter that you have set in the EM->SOA-INFRA->SOA Administration->Mediator Properties. The locker thread will cycle through 1 mediator component at a time and check if there are any requests to process from the internal queue. It will process the message(s) by changing its state to “1” for that component for processing, and then sleep for the configured interval defined in the “parallel locker thread sleep” setting before moving on to the next mediator component. If it finds no message to process, it would move on to the next, and the next, until it loops back to the first composite, where it would then process its next request.

mediator-parallel-routing-rules-2

For example: If there are 3 mediator components m1, m2, m3 with priority 1, 2, 3 then the algorithm goes as lock m1 -> sleep -> m2 -> sleep -> m3 -> sleep -> m2 -> sleep -> m3 -> sleep -> m3, in 6 iterations of locker thread, m1 messages are locked once, m2 messages are locked twice and m3 messages are locked 3 times as per the priority. All this happen in a single Locker cycle. Only after the locker thread locks the retrieved messages will they be queued for the worker threads to process the messages. So if you have many mediator components (e.g. 50 mediator components) with parallel routing rule, it will take a considerable amount of time for the locker thread to lock the message to complete one locker cycle. If you have mediator components with lower priority, it will take a longer time for the locker thread to lock the message for the low priority mediator component. The locker cycle will be reset if you undeploy or deploy a new mediator component with parallel routing rules, this is to ensure the mediator component with higher priority will be processed in the next cycle.  You will be able to observe these behaviors when you set logging level to the Trace:32 FINEST level in Oracle Enterprise Manager Fusion Middleware Control.

• oracle.soa.mediator.common
• oracle.soa.mediator.service
• oracle.soa.mediator.dispatch
• oracle.soa.mediator.serviceEngine

Example of Trace:32 diagnostic log:

[2013-12-02T16:06:21.696-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: run] Locker running
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: lockMessages] Trying to obtain locks
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: beginTransaction] Transaction  begins
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: beginTransaction] TransactionManager begin
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Obtaining locks for max rows 200
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Removing ABCS/MediatorTest!1.0*soa_e302c3ae-9b29-4bd5-802a-6052389f7be3/Mediator1 from counter 
[2013-12-02T16:06:21.697-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Obtaining locks for ABCS/MediatorTest!1.0/Mediator1 and counter 1 at index 0
[2013-12-02T16:06:21.703-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: lockMessages] Obtained locks
[2013-12-02T16:06:21.703-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: commitTransaction] Commiting Transaction
[2013-12-02T16:06:21.703-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:21.704-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:21.704-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: commitTransaction] TransactionManager commit
[2013-12-02T16:06:21.713-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: enqueueLockedMessages] Spining ...........Sleeping for 1000 milliseconds oracle.tip.mediator.dispatch.db.DeferredDBLocker
[2013-12-02T16:06:22.716-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: run] Locker running
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: lockMessages] Trying to obtain locks
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: beginTransaction] Transaction  begins
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: beginTransaction] TransactionManager begin
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Obtaining locks for max rows 200
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Removing ABCS/MediatorTest!1.0*soa_b0b789b9-0114-4138-ac50-9331e044af38/Mediator2 from counter 
[2013-12-02T16:06:22.717-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.dispatch.db] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.dispatch.db.DeferredDBLocker] [APP: soa-infra] [SRC_METHOD: lock] Obtaining locks for ABCS/MediatorTest!1.0/Mediator2 and counter 1 at index 0
[2013-12-02T16:06:22.724-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: lockMessages] Obtained locks
[2013-12-02T16:06:22.724-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: commitTransaction] Commiting Transaction
[2013-12-02T16:06:22.724-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] TransactionManager status
[2013-12-02T16:06:22.724-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: getTransactionStatus] Getting Transaction status
[2013-12-02T16:06:22.724-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.JTAHelper] [APP: soa-infra] [SRC_METHOD: commitTransaction] TransactionManager commit
[2013-12-02T16:06:22.735-07:00] [WLS_SOA1] [TRACE:32] [] [oracle.soa.mediator.common.listener] [tid: Workmanager: , Version: 0, Scheduled=false, Started=false, Wait time: 0 ms\n] [userId: <anonymous>] [ecid: a88161838353ad87:-406b0e26:142b4bfd15c:-8000-0000000000000004,0] [SRC_CLASS: oracle.tip.mediator.common.listener.DBLocker] [APP: soa-infra] [SRC_METHOD: enqueueLockedMessages] Spining ...........Sleeping for 1000 milliseconds oracle.tip.mediator.dispatch.db.DeferredDBLocker

 

After the locker thread locked the message, the worker thread will retrieve the message from the in memory queue and process the message. The number of worker thread can be tuned by changing the Parallel Worker Threads property in EM->SOA-INFRA->SOA Administration->Mediator Properties. Once the message is processed, the worker thread will change the state of the message to either “2” –Completed successfully or “3” – Faulted.

The engine was designed in order to prevent starving of threads caused by load on a single composite. What the engine wants to avoid is that, if you have a Mediator service that has received hundreds of thousands of requests and another one having received two requests, each service is given a fair amount of time to be serviced, otherwise the two requests may have to wait for hours to execute. Thus, the three settings to consider in asynchronous Mediator services are the following:

  • The Parallel Locker Thread Sleep setting: This is defined at the Mediator Service Engine level
  • The number of threads allocated to the Mediator Service Engine: This is defined by the Parallel Worker Threads parameter
  • The Priority property: Which is set at design time and applicable only to parallel routing rules

Another important point to note is when a mediator service engine is started, it registers itself in the database table called MEDIATOR_CONTAINERID_LEASE and gets a container ID. This is important because when the row is inserted into the MEDIATOR_DEFERRED_MESSAGE table, it round-robins’s the deferred message to one of its containers, the engine will then assigns the ID of the container that should process the message.

Hence, I would strongly suggest and recommend that you would take into account the list of design considerations that I have listed below when you are designing your composite using mediator parallel routing rules:

  • The priority property is only applicable to the parallel routing rules, so you need to consider the mediator component priority base on your business requirement.
  • The locker thread will cycle through all mediator components with parallel routing rules deployed in your environment regardless of whether it has been retired or shutdown.
  • Use sequential routing rules if latency is important and that you are expecting the message to be processed without delay.
  • If you have well over 100 parallel mediator components deployed in your environment, the time to complete the locker cycle grew exponentially and could not be further tuned because there is only 1 locker thread and the lowest parallel locker thread sleep time that you can set is 1 second.
  • If you have a mediator component that contain both sequential and parallel routing rules, sequential routing rules will be executed before parallel routing rules.
  • Fault policy is only applicable to parallel routing rules only. For sequential routing rules, the fault goes back to the caller and it is the responsibility of the caller to handle the fault. If the caller is an adapter, then you can define rejection handlers on the inbound adapter to take care of the errored out messages, that is, the rejected messages.

Add Your Comment