|
[
Permlink
| « Hide
]
Holger Hoffstaette added a comment - 01/May/07 02:29 AM
Does this also happen with queueEvents=false?
I set queueEvents=false, and the delay was not present. The execution for this transport was in the milliseconds.
Could you please also attach the DEBUG log with milliseconds timing enabled?
Mule Log with VM QueueEvents Enabled.
Mule Log with VM QueueEvents Disabled.
I have attached the output for queueEvents=true and queueEvents=false. With each configuration, two files are ingested and processed. The second file is not staged until the previous process has completed. Each file contains multiple records, so there are a few threads per service. Thank you for reviewing the output.
Same problem here.
After debugging, the problem is with pooling, It will pool one every 1 second. I think it's needed to make some rework thanks.- Looking at/debugging in VMMessageReceiver's getMessages method, it's clear that only one event will be pulled out of the queue at a time. Obviously, the superclass (TransactedPollingMessageReceiver) is perfectly able to handle more than one event at a time.
The poll frequency in AbstractPollingMessageReceiver is 1000ms, so the net effect is that only one event per second will be processed although more could be done in parallel. Need to think more about a proper fix for this ... the short term fix would be to drag more than one event out of the queue at a time. Forget about fixing the queue for multiple takes; it's probably better to a) reproduce the behavior first before changing anything and b) convert the VMMessageReceiver to be non-polling. I never understood why it was made this way in the first place but I am facing a similar problem with the spaces transport and it is much easier to use a receiver that immediately takes from the queue aftet receiving an item. The scheduler was meant to reduce the number of idle threads used for endpoints that really only need to be polled in larger intervals.
To clarify: with "non-polling" I meant "not periodically triggered by the connector's scheduler". Obviously the queue still has to be polled
 Forget my comments above - not using the scheduler will just create other problems (too many useless idle threads, blocking on startup etc.). The real long-term solution is to rewrite the Queue mechanism to be like NIO and not poll at all.
Regarding the poll frequency and timeouts: nothing prevents us from adjusting these default values for the VM connector (their interaction is subtle but well thought-out), however they do not explain the missing 5 seconds so I suggest to investiagate only that first. Did some fixes in http://fisheye.codehaus.org/changelog/mule/?cs=6979
 . Please test and provide feedback.The problem is very complicated and involves multiple settings interacting badly (leading to thread pool jamming); those default settings are good for external (expensive) polling but bad for in-VM. In order to account for the nonexisting latency with VM I have reduced the VM polling frequency to the smallest possible value (1ns) which effectively leads to a single scheduler thread doing a spinloop that blocks on a queue according to its queueTimeout (so no busy-wait) - kind of like the pre-1.4 behaviour but without using as many threads. Using the in-memory "persistence" this now yields >5k roundtrips from MuleClient to UMO on a single-core machine. Obviously FilePersistence is much slower but that is outside the scope of this problem. Regarding the problem of the receiver only taking a single event off the queue at a time - it would certainly be a very useful addition to provide batched dequeing instead of one-by-one polling, enabling more concurrent UMO invocations via the receiver's WorkManager.
I tested against the latest changes, with queueEvents=true. The total time for ingest (file decoding to PostgreSQL storage) remained about the same. The files were read in very quickly, but when they are read off of the queue, the db insert routines insert about 50 in the first minute (includes file reading) If I set queueEvents=false, I can see about 500 records in the database in about a minute. After reviewing this, I may be approaching the use of queueEvents wrong for my system.
I don't think we can do a GA release without this fixed, will this be in 1.4.2?
Progress is made in
closing as the described symptom is solved currently and the remaining work is described in
Have to reopen this dreadful bug as I have finally been able to recreate the conditions under which this occurs. For some reason all threads are initialised, but only the last receiver and component thread keeps getting used after some time (with #threads=8):
[12-06 20:44:34] WARN VMMessageReceiver [vmConnector.receiver.1]: getMessages() Ignore last comment; I finally did
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
 |
|
Bug
Closed
Major
VM Transport slow in 1.4 when queueEvents = "true"
