activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Adrian A <adri...@acta.co.uk>
Subject Re: Slow sending of messages
Date Thu, 24 Dec 2009 18:00:14 GMT

Hi Gary

Seasons greetings :-)

I re-created using the sample apps.

Changing the producer sample to have <property name="max" value="2000000" />
and (crudely) logging the time to send:

long start = System.currentTimeMillis();
producer.send(message);
long stop = System.currentTimeMillis();

if (stop-start > 9){
  System.out.println(new Date() + " Send took " + (stop-start));
}

results in:
<snip>
  [echo] Running producer against server at $url = tcp://localhost:61616 for
subject $subject = TEST.FOO
  [java] Connecting to URL: tcp://localhost:61616
  [java] Publishing a Message with size 1000 to queue: TEST.FOO
  [java] Using non-persistent messages
  [java] Sleeping between publish 0 ms
 [java] Thu Dec 24 17:52:51 GMT 2009 Send took 41
 [java] Thu Dec 24 17:52:55 GMT 2009 Send took 80
 [java] Thu Dec 24 17:52:57 GMT 2009 Send took 130
 [java] Thu Dec 24 17:53:01 GMT 2009 Send took 54
 [java] Thu Dec 24 17:53:04 GMT 2009 Send took 99
 [java] Thu Dec 24 17:53:08 GMT 2009 Send took 137
 [java] Thu Dec 24 17:53:08 GMT 2009 Send took 13
 [java] Thu Dec 24 17:53:11 GMT 2009 Send took 62
 [java] Thu Dec 24 17:53:16 GMT 2009 Send took 120
 [java] Thu Dec 24 17:53:20 GMT 2009 Send took 175
 [java] Thu Dec 24 17:53:25 GMT 2009 Send took 81
 [java] Thu Dec 24 17:53:30 GMT 2009 Send took 145
 [java] Thu Dec 24 17:53:34 GMT 2009 Send took 190
 [java] Thu Dec 24 17:53:39 GMT 2009 Send took 78
 [java] Thu Dec 24 17:53:44 GMT 2009 Send took 144
 [java] Thu Dec 24 17:53:49 GMT 2009 Send took 191
</snip>

This is with a locally running broker with the config at the end.

monitoring via jconsole on this queue shows:
http://old.nabble.com/file/p26916101/test%2Bfoo.png 


At the point the slow sending occurs there is a backlog in the queuesize of
between 50>100.

Logging on the GC's does show some overlap between them but not one to one.
<snip>
2009-12-24T17:52:51.709+0000: [GC [PSYoungGen: 347776K->5472K(401280K)]
357393K->15089K(428992K), 0.0428122 secs] [Times: user=0.17 sys=0.09,
real=0.04 secs]
2009-12-24T17:52:54.980+0000: [GC [PSYoungGen: 400672K->6304K(402560K)]
410289K->21281K(430272K), 0.0815947 secs] [Times: user=0.52 sys=0.02,
real=0.08 secs]
2009-12-24T17:52:57.845+0000: [GC [PSYoungGen: 401504K->6336K(457088K)]
416481K->27513K(484800K), 0.0854887 secs] [Times: user=0.45 sys=0.08,
real=0.09 secs]
2009-12-24T17:52:57.930+0000: [Full GC [PSYoungGen: 6336K->0K(457088K)]
[PSOldGen: 21177K->9515K(29440K)] 27513K->9515K(486528K) [PSPermGen:
17745K->17743K(24
secs]
2009-12-24T17:53:01.145+0000: [GC [PSYoungGen: 449152K->7744K(457536K)]
458667K->17259K(486976K), 0.0552053 secs] [Times: user=0.28 sys=0.05,
real=0.06 secs]
2009-12-24T17:53:04.360+0000: [GC [PSYoungGen: 456896K->7136K(524224K)]
466411K->24315K(553664K), 0.0998864 secs] [Times: user=0.50 sys=0.22,
real=0.10 secs]
2009-12-24T17:53:08.082+0000: [GC [PSYoungGen: 522144K->8224K(524736K)]
539323K->32451K(554176K), 0.1079863 secs] [Times: user=0.59 sys=0.08,
real=0.11 secs]
2009-12-24T17:53:08.190+0000: [Full GC [PSYoungGen: 8224K->0K(524736K)]
[PSOldGen: 24227K->9558K(31808K)] 32451K->9558K(556544K) [PSPermGen:
17746K->17746K(23
secs]
2009-12-24T17:53:11.833+0000: [GC [PSYoungGen: 515008K->8928K(603200K)]
524566K->18486K(635008K), 0.0634738 secs] [Times: user=0.39 sys=0.00,
real=0.06 secs]
2009-12-24T17:53:16.021+0000: [GC [PSYoungGen: 601696K->9312K(604096K)]
611254K->27726K(635904K), 0.1217346 secs] [Times: user=0.69 sys=0.08,
real=0.12 secs]
2009-12-24T17:53:20.284+0000: [GC [PSYoungGen: 602080K->9344K(685632K)]
620494K->36958K(717440K), 0.1316536 secs] [Times: user=0.59 sys=0.11,
real=0.13 secs]
2009-12-24T17:53:20.416+0000: [Full GC [PSYoungGen: 9344K->0K(685632K)]
[PSOldGen: 27614K->9599K(34752K)] 36958K->9599K(720384K) [PSPermGen:
17747K->17747K(22
secs]
2009-12-24T17:53:25.121+0000: [GC [PSYoungGen: 673536K->11072K(684608K)]
683135K->20671K(719360K), 0.0824521 secs] [Times: user=0.28 sys=0.19,
real=0.08 secs]
</snip>

maybe the load is just too great this example case is certainly excessive,
but it is odd that most of the time it is fine but occasionally (in these
examples 0.001% of the time) there are slow sends. something somewhere is
checkpointing, journalling / doing something causing it :-(

Any other pointers other than live with 100>1000 millisecond sends
occasionally?

thanks for yours (and everyone elses) help!

Adrian

    <broker xmlns="http://activemq.apache.org/schema/core"
brokerName="localhost" dataDirectory="${activemq.base}/data" useJmx="true"
advisorySupport="false">

        <destinationPolicy>
            <policyMap>
              <policyEntries>
                <policyEntry topic=">" producerFlowControl="false">
                  <pendingSubscriberPolicy>
                    <vmCursor />
                  </pendingSubscriberPolicy>
                </policyEntry>
                <policyEntry queue=">" producerFlowControl="false">
                  <pendingQueuePolicy>
                    <vmQueueCursor/>
                  </pendingQueuePolicy>
                </policyEntry>
              </policyEntries>
            </policyMap>
        </destinationPolicy> 

        <managementContext>
            <managementContext createConnector="true"/>
        </managementContext>

        <persistenceAdapter>
            <kahaDB directory="${activemq.base}/data/kahadb"
enableJournalDiskSyncs="false" indexWriteBatchSize="10000"
indexCacheSize="1000"/>
        </persistenceAdapter>

        <transportConnectors>
            <transportConnector name="openwire" uri="tcp://0.0.0.0:61616"/>
        </transportConnectors>
    </broker>





Gary Tully wrote:
> 
> What are your consumers doing? What does jconsole say about the queue
> depth/memory as the test runs?
> 
> This still sounds like flow control, you have
> factory.setProducerWindowSize(1024*1024); which configures a producer
> window
> which will cause the producer to block if it is full due to slow
> consumers.
> 
> possibly try using the sample producer/consumer tools that comes with the
> examples[1] or look at the source of those producers/consumers to see if
> you
> can generate something reproducible.
> 
> One other consideration for steady a enqueue rate is the store. You will
> get
> near linear performance with KahaDB but with the AMQ store, index resizing
> will occasionally cause a blip.
> 
> Happy Christmas!
> 
> [1] http://activemq.apache.org/examples.html
> 
> 2009/12/22 Adrian A <adriana@acta.co.uk>
> 
>>
>> Oh, and this is the java for creating connection
>> url =
>>
>> failover:(tcp://mq:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false&wireFormat.maxInactivityDuration=0&keepAlive=true)?maxReconnectAttempts=100
>>
>>  factory = new ActiveMQConnectionFactory(getProperties.getMQURL());
>>        factory.setDispatchAsync(false);
>>        factory.setUseAsyncSend(true);
>>        factory.setOptimizeAcknowledge(true);//if true this sends acks in
>> batches   (50% of the pre fetch size)
>>        factory.setWatchTopicAdvisories(false);
>>        factory.setCopyMessageOnSend(false);
>>        ActiveMQPrefetchPolicy pfp = new ActiveMQPrefetchPolicy();
>>        pfp.setAll(5000);
>>        factory.setPrefetchPolicy(pfp);
>>        factory.setAlwaysSessionAsync(true);
>>        factory.setProducerWindowSize(1024*1024);
>>        connection = (ActiveMQConnection) factory.createConnection();
>>
>>        connection.start();
>>
>> Session
>> new ActiveMQQueueSession((ActiveMQSession)
>> connection.createSession(false,
>> Session.AUTO_ACKNOWLEDGE));
>> or
>> connection.createSession(false, Session.AUTO_ACKNOWLEDGE);
>>
>>
>> --
>> View this message in context:
>> http://old.nabble.com/Slow-sending-of-messages-tp26849964p26891119.html
>> Sent from the ActiveMQ - User mailing list archive at Nabble.com.
>>
>>
> 
> 
> -- 
> http://blog.garytully.com
> 
> Open Source Integration
> http://fusesource.com
> 
> 

-- 
View this message in context: http://old.nabble.com/Slow-sending-of-messages-tp26849964p26916101.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.


Mime
View raw message