Skip to main content

JMS Consumer (onMessage()) delay in getting message from Oralce AQ

I have an application where I have implemented Oracle AQ. I ran in to a behavior where average time for processing varied as depicted in graph below:



In above graph when volume of orders was less, average processing time came out to be more whereas when load increased with time, average time for processing got constant and then when volume started declining, time again started increasing.

I analyzed the behavior and found that there is delay in message consumption after message has been produced to AQ. On further analysis I found that AQjmsListenerWorker goes for sleep if message is not available for consumption and sleep time doubles each time (up to peak limit) if message is not available for consumption. Thus optimizing resource utilization if there is no messages in AQ for consumption.

On enabling (-Doracle.jms.traceLevel=6) diagnostics logs for aq api. 

I analyzed that Listener thread sleep time doubles till 15000 ms (15 sec), starting with default value 1000 ms, if null message is received from AQ. See below excerpt from logs:

Thread-7 [Fri Oct 10 15:55:32 IST 2014] AQjmsListenerWorker.dispatchOneMsg:  Received the message: null message
Thread-7 [Fri Oct 10 15:55:32 IST 2014] AQjmsListenerWorker.doSleep:  try to wait for 1000 milliseconds
Thread-8 [Fri Oct 10 15:55:33 IST 2014] AQjmsListenerWorker.dispatchOneMsg:  Received the message: null message
Thread-8 [Fri Oct 10 15:55:33 IST 2014] AQjmsSimpleScheduler.feedData:  Got a null message, the sleep time is doubled to 2000
Thread-7 [Fri Oct 10 15:55:33 IST 2014] AQjmsListenerWorker.doSleep:  try to wait for 2000 milliseconds
...........

Thread-7 [Fri Oct 10 15:55:47 IST 2014] AQjmsListenerWorker.dispatchOneMsg:  Received the message: null message
Thread-7 [Fri Oct 10 15:55:47 IST 2014] AQjmsSimpleScheduler.feedData:  Got a null message, the sleep time is doubled to 15000
Thread-7 [Fri Oct 10 15:55:47 IST 2014] AQjmsListenerWorker.doSleep:  try to wait for 15000 milliseconds

So when volume was less sleep time was more.

reference:- https://community.oracle.com/thread/2535275

To reduce the sleep time I set below system properties. Thus making minimum start time to 100 ms which will double up to 4000 ms.


-Doracle.jms.minSleepTime=100

-Doracle.jms.maxSleepTime=4000

Sleep time is again set to 0 when a not null message is de-queued.

Thread-7 [Fri Oct 10 15:59:18 IST 2014] AQjmsListenerWorker.dispatchOneMsg:  Received the message: D3DD9DC7EB894ABC915CE80C180C25D5

Thread-7 [Fri Oct 10 15:59:18 IST 2014] AQjmsSimpleScheduler.feedData:  Got a non null message, the sleep time is reset to 0





Comments

Popular posts

Spark MongoDB Connector Not leading to correct count or data while reading

  We are using Scala 2.11 , Spark 2.4 and Spark MongoDB Connector 2.4.4 Use Case 1 - We wanted to read a Shareded Mongo Collection and copy its data to another Mongo Collection. We noticed that after Spark Job successful completion. Output MongoDB did not had many records. Use Case 2 -  We read a MongoDB collection and doing count on dataframe lead to different count on each execution. Analysis,  We realized that MongoDB Spark Connector is missing data on bulk read as a dataframe. We tried various partitioner, listed on page -  https://www.mongodb.com/docs/spark-connector/v2.4/configuration/  But, none of them worked for us. Finally, we tried  MongoShardedPartitioner  this lead to constant count on each execution. But, it was greater than the actual count of records on the collection. This seems to be limitation with MongoDB Spark Connector. But,  MongoShardedPartitioner  seemed closest possible solution to this kind of situation. But, it per...




Scala Spark building Jar leads java.lang.StackOverflowError

  Exception -  [Thread-3] ERROR scala_maven.ScalaCompileMojo - error: java.lang.StackOverflowError [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.generic.TraversableForwarder$class.isEmpty(TraversableForwarder.scala:36) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.mutable.ListBuffer.isEmpty(ListBuffer.scala:45) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.mutable.ListBuffer.toList(ListBuffer.scala:306) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.mutable.ListBuffer.result(ListBuffer.scala:300) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.mutable.Stack$StackBuilder.result(Stack.scala:31) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.mutable.Stack$StackBuilder.result(Stack.scala:27) [Thread-3] INFO scala_maven.ScalaCompileMojo - at scala.collection.generic.GenericCompanion.apply(GenericCompanion.scala:50) [Thread-3] INFO scala_maven.ScalaCompile...




MongoDB Chunk size many times bigger than configure chunksize (128 MB)

  Shard Shard_0 at Shard_0/xyz.com:27018 { data: '202.04GiB', docs: 117037098, chunks: 5, 'estimated data per chunk': '40.4GiB', 'estimated docs per chunk': 23407419 } --- Shard Shard_1 at Shard_1/abc.com:27018 { data: '201.86GiB', docs: 116913342, chunks: 4, 'estimated data per chunk': '50.46GiB', 'estimated docs per chunk': 29228335 } Per MongoDB-  Starting in 6.0.3, we balance by data size instead of the number of chunks. So the 128MB is now only the size of data we migrate at-a-time. So large data size per chunk is good now, as long as the data size per shard is even for the collection. refer -  https://www.mongodb.com/community/forums/t/chunk-size-many-times-bigger-than-configure-chunksize-128-mb/212616 https://www.mongodb.com/docs/v6.0/release-notes/6.0/#std-label-release-notes-6.0-balancing-policy-changes




AWS EMR Spark – Much Larger Executors are Created than Requested

  Starting EMR 5.32 and EMR 6.2 you can notice that Spark can launch much larger executors that you request in your job settings. For example - We started a Spark Job with  spark.executor.cores  =   4 But, one can see that the executors with 20 cores (instead of 4 as defined by spark.executor.cores) were launched. The reason for allocating larger executors is that there is a AWS specific Spark option spark.yarn.heterogeneousExecutors.enabled (exists in EMR only, does not exist in Open Source Spark) that is set to true by default that combines multiple executor creation requests on the same node into a larger executor container. So as the result you have fewer executor containers than you expected, each of them has more memory and cores that you specified. If you disable this option (--conf "spark.yarn.heterogeneousExecutors.enabled=false"), EMR will create containers with the specified spark.executor.memory and spark.executor.cores settings and will not co...




Hive Count Query not working

Hive with Tez execution engine -  count(*) not working , returning 0 results.  Solution -  set hive.compute.query.using.stats=false Refer -  https://cwiki.apache.org/confluence/display/Hive/Configuration+Properties hive.compute.query.using.stats Default Value:  false Added In: Hive 0.13.0 with  HIVE-5483 When set to true Hive will answer a few queries like min, max, and count(1) purely using statistics stored in the metastore. For basic statistics collection, set the configuration property  hive.stats.autogather   to true. For more advanced statistics collection, run ANALYZE TABLE queries.