Hi, 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: [EMAIL PROTECTED] [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: [EMAIL PROTECTED] [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 View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=3909823#3909823 Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=3909823 ------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Do you grep through log files for problems? Stop! Download the new AJAX search engine that makes searching your log files as easy as surfing the web. DOWNLOAD SPLUNK! http://ads.osdn.com/?ad_id=7637&alloc_id=16865&op=click _______________________________________________ JBoss-user mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/jboss-user
