putObject slows gradually with high number of objects in ca
jlukar Nov 30, 2005 11:56 AMHi, sorry for double post, but first one results in forum software croaking for some reason.
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 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