putObject slows gradually with high number of objects in Tr
Hi,
I am trying to do some performance benchmark testing and POC to see if I can use JBossCache for a high performance stock order management system that has some semi-realtime performance requirements.
I have business objects that I push into the cache and timing the putObject(). I am seeing the gradual slow down of these puts as the number of objects in the cache increase.
is this expected behaviour ?
The first fill-up-loop that inserted 10000 objects into cache had following stats: Average PUT time for 10000 objects: 12 millseconds, Smallest PUT time: 8 milliseconds, Largest PUT time: 1718 milliseconds, Total PUT time: 121295 millisconds.
In the same test case further down, I tried another fill-up-loop into the same cache for 100 business objects. The stats: Average PUT time for 100 objects: 10 millseconds, Smallest PUT time: 8 milliseconds, Largest PUT time: 42 milliseconds, Total PUT time: 1027 millisconds.
The getObject() were very fast and typcialy under 1 milisecond, which is good.
So what I am wondering is if putObject() graducal slowdown is expected behaviour or not ? If so, a 2 second put time for a business object is not acceptable in any application, regardless of real-time performance requirements or not. Can someone shed some light on this.
I have included the unit test case code along with the full output below to see if anyone can spot any missteps with my simple benchmarking. Maybe someone can suggest improvements.
JUNIT OUTPUT:
[11:34:59.227] [INFO ] [cache.PropertyConfigurator][] - Found existing property editor for org.w3c.dom.Element: org.jboss.util.propertyeditor.ElementEditor@1236cd5
[11:34:59.243] [INFO ] [cache.PropertyConfigurator][configure] - configure(): attribute size: 14
[11:34:59.248] [INFO ] [cache.TreeCache ][setClusterConfig] - setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=false;mcast_addr=228.1.2.3;mcast_port=48866;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
[11:34:59.253] [INFO ] [cache.TreeCache ][createPessimisticInterceptorChain] - interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.PessimisticLockInterceptor
class org.jboss.cache.interceptors.UnlockInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
[11:34:59.255] [INFO ] [cache.TreeCache ][_createService] - cache mode is REPL_SYNC
[11:34:59.270] [INFO ] [protocols.UDP ][createSockets] - sockets will use interface 10.58.8.75
[11:34:59.274] [INFO ] [protocols.UDP ][createSockets] - socket information:
local_addr=10.58.8.75:32883, mcast_addr=228.1.2.3:48866, bind_addr=/10.58.8.75, ttl=64
sock: bound to 10.58.8.75:32883, receive buffer size=80000, send buffer size=131071
mcast_recv_sock: bound to 10.58.8.75:48866, send buffer size=131071, receive buffer size=80000
mcast_send_sock: bound to 10.58.8.75:32884, send buffer size=131071, receive buffer size=80000
-------------------------------------------------------
GMS: address is 10.58.8.75:32883
-------------------------------------------------------
[11:35:01.285] [INFO ] [cache.TreeCache ][startService] - my local address is 10.58.8.75:32883
[11:35:01.286] [INFO ] [cache.TreeCache ][viewAccepted] - viewAccepted(): [10.58.8.75:32883|0] [10.58.8.75:32883]
[11:35:01.288] [INFO ] [cache.TreeCache ][setState] - new cache is null (may be first member in cluster)
[11:35:01.288] [INFO ] [cache.TreeCache ][fetchStateOnStartup] - state could not be retrieved (must be first member in group)
[11:35:01.290] [INFO ] [cache.TreeCache ][startService] - Cache is started!!
[11:35:01.293] [INFO ] [cache.PropertyConfigurator][] - Found existing property editor for org.w3c.dom.Element: org.jboss.util.propertyeditor.ElementEditor@be49e0
[11:35:01.328] [INFO ] [cache.PropertyConfigurator][configure] - configure(): attribute size: 14
[11:35:01.345] [INFO ] [cache.TreeCache ][setClusterConfig] - setting cluster properties from xml to: UDP(ip_mcast=true;ip_ttl=64;loopback=false;mcast_addr=228.1.2.3;mcast_port=48866;mcast_recv_buf_size=80000;mcast_send_buf_size=150000;ucast_recv_buf_size=80000;ucast_send_buf_size=150000):PING(down_thread=false;num_initial_members=3;timeout=2000;up_thread=false):MERGE2(max_interval=20000;min_interval=10000):FD_SOCK:VERIFY_SUSPECT(down_thread=false;timeout=1500;up_thread=false):pbcast.NAKACK(down_thread=false;gc_lag=50;max_xmit_size=8192;retransmit_timeout=600,1200,2400,4800;up_thread=false):UNICAST(down_thread=false;min_threshold=10;timeout=600,1200,2400;window_size=100):pbcast.STABLE(desired_avg_gossip=20000;down_thread=false;up_thread=false):FRAG(down_thread=false;frag_size=8192;up_thread=false):pbcast.GMS(join_retry_timeout=2000;join_timeout=5000;print_local_addr=true;shun=true):pbcast.STATE_TRANSFER(down_thread=true;up_thread=true)
[11:35:01.354] [INFO ] [cache.TreeCache ][createPessimisticInterceptorChain] - interceptor chain is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.PessimisticLockInterceptor
class org.jboss.cache.interceptors.UnlockInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
[11:35:01.357] [INFO ] [cache.TreeCache ][_createService] - cache mode is REPL_SYNC
[11:35:01.392] [INFO ] [protocols.UDP ][createSockets] - sockets will use interface 10.58.8.75
[11:35:01.395] [INFO ] [protocols.UDP ][createSockets] - socket information:
local_addr=10.58.8.75:32885, mcast_addr=228.1.2.3:48866, bind_addr=/10.58.8.75, ttl=64
sock: bound to 10.58.8.75:32885, receive buffer size=80000, send buffer size=131071
mcast_recv_sock: bound to 10.58.8.75:48866, send buffer size=131071, receive buffer size=80000
mcast_send_sock: bound to 10.58.8.75:32886, send buffer size=131071, receive buffer size=80000
-------------------------------------------------------
GMS: address is 10.58.8.75:32885
-------------------------------------------------------
[11:35:03.407] [INFO ] [cache.TreeCache ][startService] - my local address is 10.58.8.75:32885
[11:35:03.409] [INFO ] [cache.TreeCache ][viewAccepted] - viewAccepted(): [10.58.8.75:32883|1] [10.58.8.75:32883, 10.58.8.75:32885]
[11:35:03.411] [INFO ] [cache.TreeCache ][viewAccepted] - viewAccepted(): [10.58.8.75:32883|1] [10.58.8.75:32883, 10.58.8.75:32885]
[11:35:03.414] [INFO ] [cache.TreeCache ][_getState] - locking the / subtree to return the in-memory (transient) state
[11:35:03.416] [INFO ] [statetransfer.StateTransferGenerator_124][generateStateTransfer] - returning the in-memory state (97 bytes)
[11:35:03.417] [INFO ] [statetransfer.StateTransferGenerator_124][generateStateTransfer] - returning the associated state (4 bytes)
[11:35:03.420] [INFO ] [cache.TreeCache ][_setState] - received the state (size=167 bytes)
[11:35:03.422] [INFO ] [cache.TreeCache ][fetchStateOnStartup] - state was retrieved successfully (in 13 milliseconds)
[11:35:03.423] [INFO ] [cache.TreeCache ][startService] - Cache is started!!
[11:35:03.427] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Creating 10000 Order objects!
[11:35:03.699] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Finished Creating Order Objects. Took 270 milliseconds to create 10000 Orders!
[11:35:03.700] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Filling up cache with 10000 Orders!
[11:37:05.052] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Finished filling up cache with 10000 Orders. Took 121 Seconds to fill the cache
[11:37:05.055] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Average PUT time for 10000 objects: 12 millseconds, Smallest PUT time: 8 milliseconds, Largest PUT time: 1718 milliseconds, Total PUT time: 121295 millisconds.
[11:37:05.058] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Largest put time occured at Order Id: 9018
[11:37:05.059] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Trying another Batch Insert for 100 records!
[11:37:06.095] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Average PUT time for 100 objects: 10 millseconds, Smallest PUT time: 8 milliseconds, Largest PUT time: 42 milliseconds, Total PUT time: 1027 millisconds.
[11:37:06.309] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Size of Cache now: 10100
[11:37:06.555] [INFO ] [PrimaryCacheTest ][testPopulatingCache] - Average ACCESS time: 0Smallest ACCESS time: 0Largest ACCESS time: 77Total ACCESS time: 228
[11:37:06.923] [INFO ] [cache.TreeCache ][stopService] - stopService(): closing the channel
[11:37:06.930] [INFO ] [cache.TreeCache ][stopService] - stopService(): stopping the dispatcher
[11:37:06.932] [INFO ] [cache.TreeCache ][stopService] - stopService(): closing the channel
[11:37:06.937] [INFO ] [cache.TreeCache ][viewAccepted] - viewAccepted(): [10.58.8.75:32883|2] [10.58.8.75:32885]
[11:37:06.945] [INFO ] [cache.TreeCache ][stopService] - stopService(): stopping the dispatcher
public void testPopulatingCache() throws Exception {
long start;
long end;
int ordCount = 10000;
IOrder[] orders = new IOrder[ ordCount ];
long[] readStats = new long[ordCount];
long[] putStats = new long[ordCount];
log.info("Creating "+ordCount+ " Order objects! ");
start = System.currentTimeMillis();
for (int i = 0; i < ordCount; i++) {
orders = new MockOrder();
((MockOrder) orders).setOrderID( i );
((MockOrder) orders).setSenderId( "senderId"+i );
((MockOrder) orders).setReceiverId( "receiverId"+i );
((MockOrder) orders).setSymbol( "symbol"+i );
}
end = System.currentTimeMillis();
log.info("Finished Creating Order Objects. Took "+ ( end - start) +" milliseconds to create "+ordCount+" Orders!");
log.info("Filling up cache with "+ordCount+" Orders!");
long startBatchUpdate = System.currentTimeMillis();
for (int i = 0; i < orders.length; i++) {
start = System.currentTimeMillis();
cache1_.putObject( "/"+ orders.getOrderId(), orders );
putStats = System.currentTimeMillis() - start;
}
log.info("Finished filling up cache with "+ordCount+" Orders. Took "+ (System.currentTimeMillis() - startBatchUpdate)/1000 +" Seconds to fill the cache");
Map results = getStats(putStats);
log.info("Average PUT time for "+ordCount+" objects: "+ ((Long)results.get("total")).longValue() / putStats.length + " millseconds, "+
" Smallest PUT time: "+((Long)results.get("smallest")+" milliseconds, "+
" Largest PUT time: "+((Long)results.get("largest"))) +" milliseconds, "+
" Total PUT time: "+((Long)results.get("total")) +" millisconds." );
for (int i = 0; i < putStats.length; i++) {
long putStat = putStats;
if ( putStat == ((Long) results.get("largest")).longValue() ) {
log.info("Largest put time occured at Order Id: "+ i );
}
}
log.info("Trying another Batch Insert for 100 records!");
putStats = new long[100];
for (int i = 0; i < 100; i++) {
order = new MockOrder();
((MockOrder)order).setOrderID(1000000+i);
((MockOrder)order).setSenderId("SENDER_ID");
((MockOrder)order).setReceiverId("RECIEVER_ID");
((MockOrder)order).setSymbol("ABCD");
start = System.currentTimeMillis();
cache1_.putObject( "/"+ order.getOrderId(), order );
putStats = System.currentTimeMillis() - start;
}
results = getStats(putStats);
log.info("Average PUT time for 100 objects: "+ ((Long)results.get("total")).longValue() / putStats.length + " millseconds, "+
" Smallest PUT time: "+((Long)results.get("smallest")+" milliseconds, "+
" Largest PUT time: "+((Long)results.get("largest"))) +" milliseconds, "+
" Total PUT time: "+((Long)results.get("total")) +" millisconds." );
Map ordersMap = cache1_.findObjects("/");
log.info("Size of Cache now: "+ ordersMap.size());
Random rand = new Random();
for (int i = 0; i < readStats.length; i++) {
int someRandomOrderId = rand.nextInt( ordCount );
start = System.currentTimeMillis();
IOrder cacheOrder = (IOrder) cache1_.getObject(new Integer( someRandomOrderId ).toString());
end = System.currentTimeMillis();
readStats = end - start;
}
results = getStats(readStats);
log.info("Average ACCESS time: "+ ((Long)results.get("total")).longValue() / readStats.length +
"Smallest ACCESS time: "+((Long)results.get("smallest")+
"Largest ACCESS time: "+((Long)results.get("largest"))) +
"Total ACCESS time: "+((Long)results.get("total")));
}